Kurento / bugtracker

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

KmsLoop eats 100% CPU and segfaulted on kurento::MediaFlowState #409

Closed avssav closed 4 years ago

avssav commented 4 years ago

KMS Version: 6.12.0

Ubuntu Version: Ubuntu 16.04.6 LTS

Other libraries versions:

ii  gir1.2-gst-plugins-bad-1.5             1.8.1-1kurento4.16.04                      amd64        Description: GObject introspection data for the GStreamer libraries from the "bad" set
ii  gir1.2-gst-plugins-base-1.5            1.8.1-1kurento1.16.04                      amd64        Description: GObject introspection data for the GStreamer Plugins Base library
ii  gir1.2-gstreamer-1.5                   1.8.1-1kurento2.16.04                      amd64        Description: GObject introspection data for the GStreamer library
ii  gir1.2-nice-0.1:amd64                  0.1.15-1kurento3.16.04                     amd64        ICE library (GObject introspection)
ii  gstreamer1.5-alsa:amd64                1.8.1-1kurento1.16.04                      amd64        GStreamer plugin for ALSA
ii  gstreamer1.5-libav:amd64               1.8.1-1kurento1.16.04                      amd64        libav plugin for GStreamer
ii  gstreamer1.5-libav-dbg:amd64           1.8.1-1kurento1.16.04                      amd64        libav plugin for GStreamer (debug symbols)
ii  gstreamer1.5-nice:amd64                0.1.15-1kurento3.16.04                     amd64        ICE library (GStreamer 1.5 plugin)
ii  gstreamer1.5-nice-dbgsym:amd64         0.1.15-1kurento3.16.04                     amd64        debug symbols for package gstreamer1.5-nice
ii  gstreamer1.5-plugins-bad:amd64         1.8.1-1kurento4.16.04                      amd64        GStreamer plugins from the "bad" set
ii  gstreamer1.5-plugins-bad-dbg:amd64     1.8.1-1kurento4.16.04                      amd64        GStreamer plugins from the "bad" set (debug symbols)
ii  gstreamer1.5-plugins-base:amd64        1.8.1-1kurento1.16.04                      amd64        GStreamer plugins from the "base" set
ii  gstreamer1.5-plugins-base-dbg:amd64    1.8.1-1kurento1.16.04                      amd64        GStreamer plugins from the "base" set
ii  gstreamer1.5-plugins-good:amd64        1.8.1-1kurento2.16.04                      amd64        GStreamer plugins from the "good" set
ii  gstreamer1.5-plugins-good-dbg:amd64    1.8.1-1kurento2.16.04                      amd64        GStreamer plugins from the "good" set
ii  gstreamer1.5-plugins-ugly:amd64        1.8.1-1kurento1.16.04                      amd64        GStreamer plugins from the "ugly" set
ii  gstreamer1.5-plugins-ugly-dbg:amd64    1.8.1-1kurento1.16.04                      amd64        GStreamer plugins from the "ugly" set (debug symbols)
ii  gstreamer1.5-pulseaudio:amd64          1.8.1-1kurento2.16.04                      amd64        GStreamer plugin for PulseAudio
ii  gstreamer1.5-x:amd64                   1.8.1-1kurento1.16.04                      amd64        GStreamer plugins for X11 and Pango
ii  kms-cmake-utils                        6.12.0-0kurento1.16.04                     all          Kurento CMake utils
ii  kms-core                               6.12.0.xenial.20191015145637.503ebf7       amd64        Kurento Core module
ii  kms-core-dbg                           6.12.0.xenial.20191015145637.503ebf7       amd64        Kurento Core module
ii  kms-core-dev                           6.12.0.xenial.20191015145637.503ebf7       amd64        Kurento Core module
ii  kms-elements                           6.12.0-0kurento1.16.04                     amd64        Kurento Elements module
ii  kms-elements-dbg                       6.12.0-0kurento1.16.04                     amd64        Kurento Elements module
ii  kms-elements-dev                       6.12.0-0kurento1.16.04                     amd64        Kurento Elements module
ii  kms-filters                            6.12.0-0kurento1.16.04                     amd64        Kurento Filters module
ii  kms-filters-dbg                        6.12.0-0kurento1.16.04                     amd64        Kurento Filters module
ii  kms-filters-dev                        6.12.0-0kurento1.16.04                     amd64        Kurento Filters module
ii  kms-jsonrpc                            6.12.0-0kurento1.16.04                     amd64        Kurento JSON-RPC library
ii  kms-jsonrpc-dbg                        6.12.0-0kurento1.16.04                     amd64        Kurento JSON-RPC library
ii  kms-jsonrpc-dev                        6.12.0-0kurento1.16.04                     amd64        Kurento JSON-RPC library
ii  kmsjsoncpp                             1.6.3-1kurento1.16.04                      amd64        Kurento jsoncpp library
ii  kmsjsoncpp-dbg                         1.6.3-1kurento1.16.04                      amd64        Kurento jsoncpp library
ii  kmsjsoncpp-dev                         1.6.3-1kurento1.16.04                      amd64        Kurento jsonrpc library
ii  kurento-dbg                            6.12.0-0kurento1.16.04                     amd64        Meta-package that installs debug symbols
ii  kurento-media-server                   6.12.0-0kurento1.16.04                     amd64        Kurento Media Server
ii  kurento-media-server-dbg               6.12.0-0kurento1.16.04                     amd64        Kurento Media Server
ii  kurento-media-server-dev               6.12.0-0kurento1.16.04                     amd64        Kurento Media Server
ii  kurento-module-creator                 6.12.0-0kurento1.16.04                     all          Kurento Module Creator
ii  libgstreamer-plugins-bad1.5-0:amd64    1.8.1-1kurento4.16.04                      amd64        GStreamer development files for libraries from the "bad" set
ii  libgstreamer-plugins-bad1.5-dev        1.8.1-1kurento4.16.04                      amd64        GStreamer development files for libraries from the "bad" set
ii  libgstreamer-plugins-base1.5-0:amd64   1.8.1-1kurento1.16.04                      amd64        GStreamer libraries from the "base" set
ii  libgstreamer-plugins-base1.5-dev       1.8.1-1kurento1.16.04                      amd64        GStreamer development files for libraries from the "base" set
ii  libgstreamer1.5-0:amd64                1.8.1-1kurento2.16.04                      amd64        Core GStreamer libraries and elements
ii  libgstreamer1.5-0-dbg:amd64            1.8.1-1kurento2.16.04                      amd64        Core GStreamer libraries and elements
ii  libgstreamer1.5-dev                    1.8.1-1kurento2.16.04                      amd64        GStreamer core development files
ii  libnice-dev                            0.1.15-1kurento3.16.04                     amd64        ICE library (development files)
ii  libnice10:amd64                        0.1.15-1kurento3.16.04                     amd64        ICE library (shared library)
ii  libnice10-dbgsym:amd64                 0.1.15-1kurento3.16.04                     amd64        debug symbols for package libnice10
ii  libsrtp0:amd64                         1.6.0-0kurento1.16.04                      amd64        Secure RTP (SRTP) and UST Reference Implementations - shared library
ii  libsrtp0-dbg:amd64                     1.6.0-0kurento1.16.04                      amd64        Secure RTP (SRTP) and UST Reference Implementations - debugging symbols
ii  libusrsctp                             0.9.2-1kurento1.16.04                      amd64        sctp-refimpl library
ii  openh264                               1.4.0-1kurento1.16.04                      amd64        OpenH264 library
ii  openh264-gst-plugins-bad-1.5:amd64     1.8.1-1kurento4.16.04                      amd64        GStreamer plugins from openh264
ii  openwebrtc-gst-plugins                 0.10.0-1kurento1.16.04                     amd64        OpenWebRTC specific GStreamer plugins
ii  openwebrtc-gst-plugins-dbg             0.10.0-1kurento1.16.04                     amd64        OpenWebRTC specific GStreamer plugins
ii  openwebrtc-gst-plugins-dev             0.10.0-1kurento1.16.04                     amd64        OpenWebRTC specific GStreamer plugins

Client libraries Changed nodejs one2one-caller with dependencies "ain2": "2.0.0", "express": "~4.12.4", "kurento-client": "Kurento/kurento-client-js", "minimist": "^1.1.1", "socket.io": "2.1.1", "ws": "^7.1.0"

Browsers tested

Unknown

System description:

Our system suggests many one2one calls. We are using STUN/TURN Our clients worldwide

What steps will reproduce the problem?

Its not depends on count connections. Segfault exists with 42 one2one connections. KMS restarting. And works continue up to 69 one2one connections

What is the expected result? No segfaults

What happens instead?

2019-11-06T02:25:04+00:00 -- New execution
Segmentation fault (thread 140629711517440, pid 27522)
Stack trace:
[__nss_passwd_lookup]
sysdeps/x86_64/multiarch/memcmp-sse4.S:865
[std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::compare(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const]
/usr/lib/x86_64-linux-gnu/libstdc++.so.6:0x121278
[std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_get_insert_hint_unique_pos(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)]
/usr/include/c++/5/bits/stl_tree.h:1924
[std::_Rb_tree_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_emplace_hint_unique<std::piecewise_construct_t const&, std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>, std::tuple<> >(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::piecewise_construct_t const&, std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>&&, std::tuple<>&&)]
/usr/include/c++/5/bits/stl_tree.h:2176
[std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::shared_ptr<kurento::MediaFlowState>, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::operator[](std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)]
/usr/include/c++/5/bits/stl_map.h:483
[std::__shared_count<(__gnu_cxx::_Lock_policy)2>::~__shared_count()]
/usr/include/c++/5/bits/shared_ptr_base.h:659
[closure_invoke_notifiers]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gclosure.c:290
[accumulate]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3134
[g_signal_emit_valist]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3413 (discriminator 1)
[g_signal_emit]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3443
[check_if_flow_media]
/build/kms-core-6.12.0.xenial.20191015145637.503ebf7/src/gst-plugins/commons/kmselement.c:616
[g_timeout_dispatch]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:4577
[g_main_dispatch]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:3157
[g_main_context_iterate]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:3840
[g_main_loop_run]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:4033
[loop_thread_init]
/build/kms-core-6.12.0.xenial.20191015145637.503ebf7/src/gst-plugins/commons/kmsloop.c:105

2019-11-06T14:08:50+00:00 -- New execution
prlanzarin commented 4 years ago

@avssav Do you have the full logs for the crashed session? Hoping we can infer something about the crash from the log behavior.

j1elo commented 4 years ago
ii  kms-core      6.12.0.xenial.20191015145637.503ebf7  amd64  Kurento Core module
ii  kms-elements  6.12.0-0kurento1.16.04                amd64  Kurento Elements module
ii  kms-filters   6.12.0-0kurento1.16.04                amd64  Kurento Filters module

The KMS installation is 6.12.0 release, but kms-core is not. Are you working on a customized fork of kms-core?

j1elo commented 4 years ago

If you are working with a customized fork: run with AddressSanitizer to detect possible memory corruption bugs.

This is made easier by the script kms-build-run.sh, you would follow the instructions given in Building from sources, but running like this:

./bin/kms-build-run.sh --address-sanitizer

If you are NOT running with a fork: your installation is borked. Make sure you uninstall all of Kurento: Clean up your system

And then, reinstall everything from scratch: Local Installation

Alternatively, just use the Docker image.

avssav commented 4 years ago

Do you have the full logs for the crashed session? Hoping we can infer something about the crash from the log behavior.

Crush-dump file not created. I don't see anything unusual in logfiles

ubuntu@kms2:/var/log/kurento-media-server$ tail -n100 2019-11-06T022504.00000.pid27522.log
2019-11-06T14:07:46,931329 27522 0x00007fe5c3332700 warning rtpsynchronizer           kmsrtpsynchronizer.c:539 kms_rtp_synchronizer_process_rtp_buffer_mapped() <KmsRtpSynchronizer@0x7fe6fc2286e0>  [Sorted mode] Fix PTS not increasing monotonically, SSRC: 2541607815, seq: 31522, rtp_ts: 3386673774, ext_ts: 3386673774, last: 0:08:01.593638561, current: 0:08:01.569357561, fixed = last: 0:08:01.593638561
2019-11-06T14:07:46,931417 27522 0x00007fe5c3332700 warning kmsutils                  kmsutils.c:1427 kms_utils_depayloader_adjust_pts_out() <rtpopusdepay1175>  Fix PTS not strictly increasing, last: 0:08:01.601638561, current: 0:08:01.593638561, fixed = last + 1: 0:08:01.602638561
2019-11-06T14:07:46,945295 27522 0x00007fe5c3332700 warning rtpsynchronizer           kmsrtpsynchronizer.c:539 kms_rtp_synchronizer_process_rtp_buffer_mapped() <KmsRtpSynchronizer@0x7fe6fc2286e0>  [Sorted mode] Fix PTS not increasing monotonically, SSRC: 2541607815, seq: 31523, rtp_ts: 3386674734, ext_ts: 3386674734, last: 0:08:01.593638561, current: 0:08:01.589357561, fixed = last: 0:08:01.593638561
2019-11-06T14:07:46,945400 27522 0x00007fe5c3332700 warning kmsutils                  kmsutils.c:1427 kms_utils_depayloader_adjust_pts_out() <rtpopusdepay1175>  Fix PTS not strictly increasing, last: 0:08:01.602638561, current: 0:08:01.593638561, fixed = last + 1: 0:08:01.603638561
2019-11-06T14:07:46,988195 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:47,022112 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.108869327, duration: 0:00:00.033397326
2019-11-06T14:07:47,055482 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.142266653, duration: 0:00:00.033397326
2019-11-06T14:07:47,088836 27522 0x00007fe61fbeb700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 28807, expected 28815)
2019-11-06T14:07:47,089245 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.175663979, duration: 0:00:00.033397326
2019-11-06T14:07:47,103791 27522 0x00007fe5121d0700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 33389, expected 33392)
2019-11-06T14:07:47,112713 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 29377, expected 29384)
2019-11-06T14:07:47,112792 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 29378, expected 29384)
2019-11-06T14:07:47,122367 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.209061305, duration: 0:00:00.033397326
2019-11-06T14:07:47,122482 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:461 discont_detection_probe() <kmsagnosticbin2-2462:sink>  Stream discontinuity detected on non-keyframe
2019-11-06T14:07:47,145299 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:47,183507 27522 0x00007fe5121d0700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 33390, expected 33392)
2019-11-06T14:07:47,204759 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 18157, expected 18159)
2019-11-06T14:07:47,229729 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:47,275558 27522 0x00007fe4d014c700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 45651, expected 45653)
2019-11-06T14:07:47,299104 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.385832343, duration: 0:00:00.041341811
2019-11-06T14:07:47,300689 27522 0x00007fe5121d0700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 33389, expected 33394)
2019-11-06T14:07:47,312899 27522 0x00007fe5121d0700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 33390, expected 33394)
2019-11-06T14:07:47,340394 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.427174154, duration: 0:00:00.041341811
2019-11-06T14:07:47,381744 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.468515965, duration: 0:00:00.041341811
2019-11-06T14:07:47,399327 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:47,423086 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.509857776, duration: 0:00:00.041341811
2019-11-06T14:07:47,464421 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.551199587, duration: 0:00:00.041341811
2019-11-06T14:07:47,470460 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:47,479107 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26647, expected 26649)
2019-11-06T14:07:47,505757 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.592541398, duration: 0:00:00.041341811
2019-11-06T14:07:47,547126 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.633883209, duration: 0:00:00.041341811
2019-11-06T14:07:47,588441 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:38.675225020, duration: 0:00:00.041341811
2019-11-06T14:07:47,615755 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 29387, expected 29396)
2019-11-06T14:07:47,615858 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 29388, expected 29396)
2019-11-06T14:07:47,631043 27522 0x00007fe61fbeb700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 28829, expected 28832)
2019-11-06T14:07:47,636299 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:47,659269 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:47,667686 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:47,726938 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:47,730917 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26647, expected 26666)
2019-11-06T14:07:47,872355 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:47,943556 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:39.030258062, duration: 0:00:00.070783484
2019-11-06T14:07:47,970072 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:48,014289 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:39.101041546, duration: 0:00:00.070783484
2019-11-06T14:07:48,021223 27522 0x00007fe61fbeb700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 28829, expected 28843)
2019-11-06T14:07:48,050473 27522 0x00007fe63140e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 43187, expected 43189)
2019-11-06T14:07:48,085330 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:39.171825030, duration: 0:00:00.070783484
2019-11-06T14:07:48,091718 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 29396, expected 29404)
2019-11-06T14:07:48,117310 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:48,177722 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26696, expected 26698)
2019-11-06T14:07:48,190418 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:48,202569 27522 0x00007fe55ea69700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 37117, expected 37119)
2019-11-06T14:07:48,245890 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:39.332618352, duration: 0:00:00.069929481
2019-11-06T14:07:48,246004 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:461 discont_detection_probe() <kmsagnosticbin2-2462:sink>  Stream discontinuity detected on non-keyframe
2019-11-06T14:07:48,253936 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26701, expected 26703)
2019-11-06T14:07:48,278682 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26703, expected 26705)
2019-11-06T14:07:48,368520 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:48,435670 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26696, expected 26714)
2019-11-06T14:07:48,449916 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:48,487572 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:39.574349999, duration: 0:00:00.052764826
2019-11-06T14:07:48,508674 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26701, expected 26719)
2019-11-06T14:07:48,526086 27522 0x00007fe5121d0700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 33404, expected 33411)
2019-11-06T14:07:48,540332 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:39.627114825, duration: 0:00:00.052764826
2019-11-06T14:07:48,554956 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26703, expected 26721)
2019-11-06T14:07:48,591334 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:48,593099 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:39.679879651, duration: 0:00:00.052764826
2019-11-06T14:07:48,627321 27522 0x00007fe6e568d700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 15681, expected 15686)
2019-11-06T14:07:48,643520 27522 0x00007fe584ab5700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 27994, expected 27999)
2019-11-06T14:07:48,672807 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:48,679877 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26730, expected 26732)
2019-11-06T14:07:48,729411 27522 0x00007fe5121d0700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 33404, expected 33413)
2019-11-06T14:07:48,843327 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:48,844726 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 18240, expected 18242)
2019-11-06T14:07:48,857298 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:39.943905023, duration: 0:00:00.181354136
2019-11-06T14:07:48,880368 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:48,914478 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26753, expected 26755)
2019-11-06T14:07:48,916680 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 18244, expected 18246)
2019-11-06T14:07:48,934874 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26730, expected 26755)
2019-11-06T14:07:49,038648 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:40.125259159, duration: 0:00:00.181354136
2019-11-06T14:07:49,039014 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:461 discont_detection_probe() <kmsagnosticbin2-2462:sink>  Stream discontinuity detected on non-keyframe
2019-11-06T14:07:49,081479 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:49,146030 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:49,164189 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26753, expected 26770)
2019-11-06T14:07:49,196806 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 29409, expected 29417)
2019-11-06T14:07:49,235722 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 29410, expected 29417)
2019-11-06T14:07:49,309937 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:40.396604951, duration: 0:00:00.089991656
2019-11-06T14:07:49,323454 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:49,399822 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:40.486596607, duration: 0:00:00.089991656
2019-11-06T14:07:49,404436 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
2019-11-06T14:07:49,558494 27522 0x00007fe5fe3a8700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2339:sink>  Stream gap detected, timestamp: 0:08:11.444828189, duration: 0:00:00.120501671
2019-11-06T14:07:49,558872 27522 0x00007fe5fe3a8700 warning kmsutils                  kmsutils.c:461 discont_detection_probe() <kmsagnosticbin2-2339:sink>  Stream discontinuity detected on non-keyframe
2019-11-06T14:07:49,561655 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:49,626364 27522 0x00007fe653452700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 22847, expected 22853)
2019-11-06T14:07:49,682027 27522 0x00007fe635416700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 26799, expected 26801)
2019-11-06T14:07:49,692559 27522 0x00007fe69ece9700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 43082, expected 43084)
2019-11-06T14:07:49,711191 27522 0x00007fe5259f7700 warning kmsutils                  kmsutils.c:483 gap_detection_probe() <kmsagnosticbin2-2462:sink>  Stream gap detected, timestamp: 0:03:40.793660209, duration: 0:00:00.169035352
2019-11-06T14:07:49,717743 27522 0x00007fe61fbeb700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 28891, expected 28894)
2019-11-06T14:07:49,803325 27522 0x00007fe5a92fe700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1284>  offset unusually large, ignoring
2019-11-06T14:07:49,822189 27522 0x00007fe4b110e700 warning rtpsource                 rtpsource.c:1147 update_receiver_stats()  duplicate or reordered packet (seqnr 29417, expected 29422)
2019-11-06T14:07:49,850033 27522 0x00007fe6e66cd700 warning rtpbin                    gstrtpbin.c:1156 stream_set_ts_offset() <rtpbin1235>  offset unusually large, ignoring
avssav commented 4 years ago
ii  kms-core      6.12.0.xenial.20191015145637.503ebf7  amd64  Kurento Core module
ii  kms-elements  6.12.0-0kurento1.16.04                amd64  Kurento Elements module
ii  kms-filters   6.12.0-0kurento1.16.04                amd64  Kurento Filters module

The KMS installation is 6.12.0 release, but kms-core is not. Are you working on a customized fork of kms-core?

We are building our kms-core with a small patch. I suppose this doesn't affect

ubuntu@kurento:~/6.12.0/packages/kms-core/patches$ cat kmsbasertpendpoint.patch
--- a/src/gst-plugins/commons/kmsbasertpendpoint.c      2018-05-22 12:07:42.000000000 +0000
+++ b/src/gst-plugins/commons/kmsbasertpendpoint.c      2018-05-22 12:07:04.928187314 +0000
@@ -92,6 +92,8 @@
   __pos;                      \
 })

+#define PAYLOADER_MTU 1100
+
 typedef struct _KmsSSRCStats KmsSSRCStats;
 struct _KmsSSRCStats
 {
@@ -1204,6 +1206,7 @@
   }

   payloader = gst_element_factory_create (factory, NULL);
+  g_object_set (payloader, "mtu", PAYLOADER_MTU, NULL);

   pspec = g_object_class_find_property (G_OBJECT_GET_CLASS (payloader), "pt");
   if (pspec != NULL && G_PARAM_SPEC_VALUE_TYPE (pspec) == G_TYPE_UINT) {

I wanted to propose the patch to mainline with adding MTU parameter to kms-core/src/server/config/BaseRtpEndpoint.conf.ini, but unfortunately I'm not programmer and I can not change the code as needed (

avssav commented 4 years ago

Yesterday I changed aws instance of our KMS from c5.xlarge to c5.2xlarge (expecting a higher load today). And today KMS segfalted again. But it was with crashdump file. There were 59 one2one-call. Not maximum on today. End of log file (grep -e fixme -e dtls)

ubuntu@kms2:/var/log/kurento-media-server$ tail -n1000 2019-11-14T022503.00000.pid5429.log |grep -e fixme -e dtls
2019-11-14T16:31:50,857659 5429 0x00007fc34fb10700   fixme basesink                  gstbasesink.c:3125 gst_base_sink_default_event() <nicesink3368>  stream-start event without group-id. Consider implementing group-id handling in the upstream elements
2019-11-14T16:31:50,857921 5429 0x00007fc6230b6700   fixme default                   gstutils.c:3766 gst_pad_create_stream_id_internal() <nicesrc3368:src>  Creating random stream-id, consider implementing a deterministic way of creating a stream-id
2019-11-14T16:31:51,045900 5429 0x00007fc61e0ac700   fixme default                   gstutils.c:3766 gst_pad_create_stream_id_internal() <videoSrc:src>  Creating random stream-id, consider implementing a deterministic way of creating a stream-id
2019-11-14T16:31:51,045929 5429 0x00007fc5f8060700   fixme default                   gstutils.c:3766 gst_pad_create_stream_id_internal() <audioSrc:src>  Creating random stream-id, consider implementing a deterministic way of creating a stream-id
2019-11-14T16:31:51,151498 5429 0x00007fc5ef84f700   fixme default                   gstutils.c:3766 gst_pad_create_stream_id_internal() <videoSrc:src>  Creating random stream-id, consider implementing a deterministic way of creating a stream-id
2019-11-14T16:31:51,151691 5429 0x00007fc571753700   fixme default                   gstutils.c:3766 gst_pad_create_stream_id_internal() <audioSrc:src>  Creating random stream-id, consider implementing a deterministic way of creating a stream-id
2019-11-14T16:31:51,163089 5429 0x00007fc4f5e5c700   fixme basesink                  gstbasesink.c:3125 gst_base_sink_default_event() <nicesink3369>  stream-start event without group-id. Consider implementing group-id handling in the upstream elements
2019-11-14T16:31:51,163659 5429 0x00007fc4f0e52700   fixme default                   gstutils.c:3766 gst_pad_create_stream_id_internal() <nicesrc3369:src>  Creating random stream-id, consider implementing a deterministic way of creating a stream-id
2019-11-14T16:31:51,937116 5429 0x00007fc6230b6700 warning dtlssrtpdemux             gstdtlssrtpdemux.c:137 sink_chain() <dtls-srtp-demux>  received invalid buffer: 1
2019-11-14T16:31:52,347456 5429 0x00007fc61e0ac700   fixme basesink                  gstbasesink.c:3125 gst_base_sink_default_event() <filesink3299>  stream-start event without group-id. Consider implementing group-id handling in the upstream elements
2019-11-14T16:31:52,549017 5429 0x00007fc5ef84f700   fixme basesink                  gstbasesink.c:3125 gst_base_sink_default_event() <filesink3300>  stream-start event without group-id. Consider implementing group-id handling in the upstream elements
2019-11-14T16:31:57,115603 5429 0x00007fc364339700 warning dtlssrtpdemux             gstdtlssrtpdemux.c:137 sink_chain() <dtls-srtp-demux>  received invalid buffer: 1

error.log

(kurento-media-server:5429): GStreamer-CRITICAL **: Element rtpbin1605 already has a pad named send_rtp_sink_0, the behaviour of  gst_element_get_request_pad() for existing pads is undefined!

(kurento-media-server:5429): GStreamer-CRITICAL **: Element rtpbin1605 already has a pad named send_rtp_sink_1, the behaviour of  gst_element_get_request_pad() for existing pads is undefined!

(kurento-media-server:5429): GStreamer-CRITICAL **: Element rtpbin1605 already has a pad named send_rtp_sink_0, the behaviour of  gst_element_get_request_pad() for existing pads is undefined!

(kurento-media-server:5429): GStreamer-CRITICAL **: Element rtpbin1605 already has a pad named send_rtp_sink_1, the behaviour of  gst_element_get_request_pad() for existing pads is undefined!

(kurento-media-server:5429): GStreamer-CRITICAL **: Padname '':src_0 does not belong to element kmsagnosticbin2-2999 when removing
Segmentation fault (thread 140491400148736, pid 5429)
Stack trace:
[__nss_passwd_lookup]
sysdeps/x86_64/multiarch/memcmp-sse4.S:865
[std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::compare(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const]
/usr/lib/x86_64-linux-gnu/libstdc++.so.6:0x121278
[std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_get_insert_hint_unique_pos(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)]
/usr/include/c++/5/bits/stl_tree.h:1924
[std::_Rb_tree_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_emplace_hint_unique<std::piecewise_construct_t const&, std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>, std::tuple<> >(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::piecewise_construct_t const&, std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>&&, std::tuple<>&&)]
/usr/include/c++/5/bits/stl_tree.h:2176
[std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::shared_ptr<kurento::MediaFlowState>, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::operator[](std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)]
/usr/include/c++/5/bits/stl_map.h:483
[std::__shared_count<(__gnu_cxx::_Lock_policy)2>::~__shared_count()]
/usr/include/c++/5/bits/shared_ptr_base.h:659
[closure_invoke_notifiers]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gclosure.c:290
[accumulate]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3134
[g_signal_emit_valist]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3413 (discriminator 1)
[g_signal_emit]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3443
[check_if_flow_media]
/build/kms-core-6.12.0.xenial.20191015145637.503ebf7/src/gst-plugins/commons/kmselement.c:616
[g_timeout_dispatch]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:4577
[g_main_dispatch]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:3157
[g_main_context_iterate]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:3840
[g_main_loop_run]
/build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:4033
[loop_thread_init]
/build/kms-core-6.12.0.xenial.20191015145637.503ebf7/src/gst-plugins/commons/kmsloop.c:105

2019-11-14T16:32:32+00:00 -- New execution

Backtrace

[New LWP 20673]
[New LWP 21459]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/bin/kurento-media-server'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007fc9bf91b428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
54  ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
[Current thread is 1 (Thread 0x7fc6b3fff700 (LWP 7010))]
(gdb) bt
#0  0x00007fc9bf91b428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#1  0x00007fc9bf91d02a in __GI_abort () at abort.c:89
#2  0x0000559241338909 in Debug::DeathHandler::SignalHandler(int, void*, void*) () at /workdir/server/death_handler.cpp:299
#3  0x0000559241338909 in Debug::DeathHandler::SignalHandler(int, void*, void*) (sig=<optimized out>, secret=<optimized out>) at /workdir/server/death_handler.cpp:600
#4  0x00007fc9c203c390 in <signal handler called> () at /lib/x86_64-linux-gnu/libpthread.so.0
#5  0x00007fc9bfa550c0 in __memcmp_sse4_1 () at ../sysdeps/x86_64/multiarch/memcmp-sse4.S:865
#6  0x00007fc9bffe7278 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::compare(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) const () at /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x00007fc9c0c12423 in std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_get_insert_hint_unique_pos(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (__rhs="audio_default", __lhs="")
    at /usr/include/c++/5/bits/basic_string.h:4989
#8  0x00007fc9c0c12423 in std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_get_insert_hint_unique_pos(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (this=0x7fc6e028e9b8, __y="audio_default", __x="")
    at /usr/include/c++/5/bits/stl_function.h:387
#9  0x00007fc9c0c12423 in std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_get_insert_hint_unique_pos(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) (this=this@entry=0x7fc6e028e9b8, __position=__position@entry=..., __k="audio_default") at /usr/include/c++/5/bits/stl_tree.h:1924
#10 0x00007fc9c0c12572 in std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_emplace_hint_unique<std::piecewise_construct_t const&, std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>, std::tuple<> >(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::piecewise_construct_t const&, std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>&&, std::tuple<>&&) (this=this@entry=0x7fc6e028e9b8, __pos=__pos@entry=...) at /usr/include/c++/5/bits/stl_tree.h:2174
#11 0x00007fc9c0c06828 in kurento::MediaElementImpl::mediaFlowOutStateChange(int, char*, KmsElementPadType) (__k="audio_default", this=0x7fc6e028e9b8) at /usr/include/c++/5/bits/stl_map.h:483
#12 0x00007fc9c0c06828 in kurento::MediaElementImpl::mediaFlowOutStateChange(int, char*, KmsElementPadType) (this=0x7fc6e028e800, isFlowing=<optimized out>, padName=0x7fc6c473ac80 "default", type=KMS_ELEMENT_PAD_TYPE_AUDIO) at /build/kms-core-6.12.0.xenial.20191015145637.503ebf7/src/server/implementation/objects/MediaElementImpl.cpp:476
#13 0x00007fc9c0c00649 in kurento::signal_handler_adaptor<void, _GstElement*, int, char*, KmsElementPadType>(gpointer) (__args#3=KMS_ELEMENT_PAD_TYPE_AUDIO, __args#2=0x7fc6c473ac80 "default", __args#1=0, __args#0=0x7fc6e82096e0 [KmsWebrtcEndpoint], this=<optimized out>) at /usr/include/c++/5/functional:2267
#14 0x00007fc9c0c00649 in kurento::signal_handler_adaptor<void, _GstElement*, int, char*, KmsElementPadType>(gpointer) (data=<optimized out>)
    at /build/kms-core-6.12.0.xenial.20191015145637.503ebf7/src/server/implementation/SignalHandler.hpp:54
#18 0x00007fc9c122708f in <emit signal ??? on instance 0x7fc6e82096e0 [KmsWebrtcEndpoint]> (instance=<optimized out>, signal_id=signal_id@entry=22, detail=detail@entry=0)
    at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3441
    #15 0x00007fc9c120bfa5 in g_closure_invoke (closure=0x7fc6e00f7070, return_value=return_value@entry=0x0, n_param_values=4, param_values=param_values@entry=0x7fc6b3ffdfb0, invocation_hint=invocation_hint@entry=0x7fc6b3ffdf30) at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gclosure.c:804
    #16 0x00007fc9c121dfc1 in signal_emit_unlocked_R (node=node@entry=0x7fc6c800a610, detail=detail@entry=0, instance=instance@entry=0x7fc6e82096e0, emission_return=emission_return@entry=0x0, instance_and_params=instance_and_params@entry=0x7fc6b3ffdfb0) at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3629
    #17 0x00007fc9c1226d5c in g_signal_emit_valist (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>, var_args=var_args@entry=0x7fc6b3ffe1a0)
    at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./gobject/gsignal.c:3385
#19 0x00007fc9be91eac6 in check_if_flow_media (user_data=<error reading variable: value has been optimized out>)
    at /build/kms-core-6.12.0.xenial.20191015145637.503ebf7/src/gst-plugins/commons/kmselement.c:616
#20 0x00007fc9c0f35ab3 in g_timeout_dispatch (source=0x7fc7301caad0, callback=<optimized out>, user_data=<optimized out>) at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:4577
#21 0x00007fc9c0f3504a in g_main_context_dispatch (context=0x7fc6c4001df0) at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:3154
#22 0x00007fc9c0f3504a in g_main_context_dispatch (context=context@entry=0x7fc6c4001df0) at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:3769
#23 0x00007fc9c0f353f0 in g_main_context_iterate (context=0x7fc6c4001df0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:3840
#24 0x00007fc9c0f35712 in g_main_loop_run (loop=0x7fc6c4001ba0) at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gmain.c:4034
#25 0x00007fc9be920325 in loop_thread_init (data=<optimized out>) at /build/kms-core-6.12.0.xenial.20191015145637.503ebf7/src/gst-plugins/commons/kmsloop.c:104
#26 0x00007fc9c0f5bc55 in g_thread_proxy (data=0x7fc6bc006a80) at /build/glib2.0-pjKWYQ/glib2.0-2.48.2/./glib/gthread.c:780
#27 0x00007fc9c20326ba in start_thread (arg=0x7fc6b3fff700) at pthread_create.c:333
#28 0x00007fc9bf9ed41d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
j1elo commented 4 years ago
kurento::MediaElementImpl::mediaFlowOutStateChange

I'm afraid the fatal bug is back from the death... or better said it was never 100% fixed, apparently: MediaFlowInStateChange Seg Fault #393

That was a very hard to fix bug, but now your symptoms are very similar so I'm inclined to think that it's actually the same issue. Bug #393 ended up being (apparently) fixed with better thread-safety around emitting signals (from KMS to the client), so maybe there is still some work we have to do around them.

avssav commented 4 years ago

A little earlier than you closed #393 , I tried add the following debug configuration /etc/default/kurento-media-server, which gets more information export GST_DEBUG="${GST_DEBUG:-3},KurentoMediaElementImpl:5" KMS worked slower, the log file grows up, but MediaFlownInStateChange Segfalt is less common or disappears

Maybe this information will help other people who have the same problems.

j1elo commented 4 years ago

Could you please try to run Kurento from our AddressSanitizer Docker image?

It contains all of Kurento server specially built to run with AddressSanitizer, and could help finding memory access errors (the cause for this crash):

docker run --name kms-asan -p 8888:8888 kurento/kurento-media-server:6.12.0-asan
avssav commented 4 years ago

Now I can't run kms-asan for production because your KMS in docker image compiled without our MTU patch. I could run it if you wloud add support config MTU parameter to kms-core

j1elo commented 4 years ago

The MTU used by Google Chrome is 1200 B; they seem to consider that it is the best compromise for good network behavior (see: Why RTP max packet size is 1200 in WebRTC?).

Kurento uses GStreamer's default of 1400, but we could consider moving to the 1200 used by Chrome, which is after all the main implementation of WebRTC.

What problem did you find that needs a MTU of 1100?

avssav commented 4 years ago

It's legacy (2 years ago) configuration from previous sysadmin of our company. He tried compiled with MTU=1300 B, but it not helps to us. This is an arbitrarily selected value to avoid packet fragmentation. There is no any exact science behind this. Maybe some clients with rare type of internet connection (example, something like a double VPN connection over PPPoE or maybe IPsec) had problems with connect to our KMS. We haven't resources to experiments and check exactly all values (ex. 1101, 1102,....,1200, 1201 bytes etc). 1100 is works. And it is enough.

Maybe for another users of kurento will be useful other MTU values. In addition to Chrome, there are our clients use others browsers (Safari on iPads, Firefox). Are there MTU hardcoded too?

j1elo commented 4 years ago

You might want to test with 1200, as that's what all browsers use. I guess they found that this number is good for 99% use cases. I am even thinking of changing Kurento to use 1200, instead of the current 1400 (default from GStreamer library).

All browsers use libwebrtc from webrtc.org, so this means that all use the same 1200 MTU:

j1elo commented 4 years ago

@avssav having the ability to change the MTU seemed that wouldn't hurt, so I've added it to the Kurento client API in the nightly build: https://doc-kurento.readthedocs.io/en/latest/_static/client-javadoc/org/kurento/client/BaseRtpEndpoint.html#setMtu-int-

~You should now be able to use the API method, or the mtu parameter in BaseRtpEndpoint.conf.ini.~

~Please if you still see the crash related to this bug report, run Kurento with the latest AddressSanitizer nightly image:~

j1elo commented 4 years ago

Sorry, the images needed an update. You should now be able to either use:

Please if you still see the crash related to this bug report, run Kurento with the latest AddressSanitizer nightly image (getting created right now):

docker run --name kms-asan -p 8888:8888 \
    -e KMS_MTU="1100" \
    kurento/kurento-media-server-dev:6.12.1-20191121162815-asan
avssav commented 4 years ago

I started next command in our QA environment:

docker run --name kms-asan --restart always -p 8888:8888 -e KMS_MTU="1100" \
   -v $HOME/kurento-config/kurento-media-server:/etc/default/kurento-media-server \
   -v $HOME/kurento-config/kurento:/kurento-asan/config -v $HOME/tmp/kurento:/tmp \
   -d kurento/kurento-media-server-dev:6.12.1-20191121163445-asan

I put my cert.pem and kurento.conf.json (with TURN-config) to config directory. I think debug-file will create in $HOME/tmp/kurento But I don't understand where will I get special debug ASAN logs?

Now, I see in docker logs kms-asan next strings:

0:00:00.334506810    10 0x61900008ccc0 WARN                 default gstsf.c:98:gst_sf_create_audio_template_caps: format 0x160000: 'SD2 (Sound Designer II)' is not mapped
0:00:00.334522120    10 0x61900008ccc0 WARN                 default gstsf.c:98:gst_sf_create_audio_template_caps: format 0x190000: 'WVE (Psion Series 3)' is not mapped
==10==LeakSanitizer has encountered a fatal error.
==10==HINT: For debugging, try setting environment variable LSAN_OPTIONS=verbosity=1:log_threads=1
==10==HINT: LeakSanitizer does not work under ptrace (strace, gdb, etc)
0:00:00.440473436     9 0x619000114ac0 INFO    KurentoModuleManager ModuleManager.cpp:90:loadModule: Load file: /kurento-asan/libkmselementsmodule.so, module name: /kurento-asan/libkmselementsmodule.so
0:00:00.440730250     9 0x619000114ac0 INFO    KurentoModuleManager ModuleManager.cpp:137:loadModule: Loaded module: elements, version: 6.12.1~17.gcbe7516, date: Nov 21 2019 15:50:50

And I see one more unimportant little thing. I added DAEMON_MAX_FILES="$(( ($(cat /proc/sys/fs/file-max) * 50) / 100 ))" (it is must be 4194304) to /etc/default/kurento-media-server but I see

root@2d2ffaa46fb2:/kurento-asan# cat /proc/9/limits |grep open
Max open files            1048576              1048576              files
avssav commented 4 years ago

But I don't understand where will I get special debug ASAN logs?

I see. After I do kill -9 pid_kurento process i see old and new log in docker logs kms-asan

j1elo commented 4 years ago

Yes, have a look at the docker logs doc for more info about that command.

You run kurento-asan, for example:

docker run --name kms-asan -p 8888:8888 kurento/kurento-media-server-dev:latest-asan

And later you can inspect the logs with the standard logs command from Docker,

docker logs kms-asan

docker logs kms-asan can also be run without killing the process, while it is running. You can think of it like running tail or less on a typical Kurento log. You can also "follow" it, like with tail -f:

docker logs --follow kms-asan

then leave it running until the crash happens. You should see some error from AddressSanitizer:

=================================================================
==11==ERROR: AddressSanitizer detected memory error ...

then share it here.

The first LeakSanitizer error is a false positive. Don't include that one.

avssav commented 4 years ago

@j1elo Could you include parameter DAEMON_MAX_FILES to docker container environment? After that I will run kurento-media-server-dev:xxx-asan on our production environment for detect possible memory corruption bugs. Now we have next kernel config tuning for c5.xlarge and c5.2xlarge instances:

ubuntu@kms2:~$ cat /etc/sysctl.conf |grep -v ^#|grep -v ^$
net.ipv4.ip_forward=1
net.core.somaxconn=32768
net.core.netdev_max_backlog=50000
net.ipv4.tcp_max_syn_backlog=32768
net.core.rmem_max=33554432
net.core.wmem_max=33554432
net.core.rmem_default=8388608
net.core.wmem_default=8388608
net.ipv4.tcp_rmem=2097152 8388608 33554432
net.ipv4.tcp_wmem=2097152 8388608 33554432
net.ipv4.udp_mem=2097152 4194304  8388608
fs.nr_open=16777216
fs.file-max=8388608
net.ipv4.tcp_fin_timeout=20
fs.inotify.max_user_watches=16777216
fs.inotify.max_queued_events=65536
j1elo commented 4 years ago

Hi, that's not part of the public environment vars we want to share in the docker images; for advanced settings such as that one, you can volume mount the settings file as you did in your previous command, and change the value in there.

avssav commented 4 years ago

I started KMS in our production environment:

docker run --name kms-asan --restart always -p 8888:8888 -p 8433:8433 -e KMS_MTU="1100" \
    --ulimit nofile="$(( ($(cat /proc/sys/fs/file-max) * 50) / 100 ))" --log-driver journald \
    -v $HOME/kurento-config/kurento-media-server:/etc/default/kurento-media-server \
    -v $HOME/kurento-config/kurento:/kurento-asan/config \
    -v $HOME/tmp/kurento:/tmp -d kurento/kurento-media-server-dev:6.12.1-20191121163445-asan
j1elo commented 4 years ago

Great! Note that:

avssav commented 4 years ago

I caught some segfaults by kurento/kurento-media-server-dev:6.12.1-20191128192142-asan image. They have the same stack trace

Jan 17 16:51:41 kms 89a2a187849b[1160]: 14:26:28.279517582    11 0x61d005a20370 WARN                  rtpbin gstrtpbin.c:1156:stream_set_ts_offset:<rtpbin2768> offset unusually large, ignoring
Jan 17 16:51:41 kms 89a2a187849b[1160]: 14:26:28.374200442    11 0x61d0016f85e0 WARN               rtpsource rtpsource.c:1147:update_receiver_stats: duplicate or reordered packet (seqnr 32448, expected 32450)
Jan 17 16:51:41 kms 89a2a187849b[1160]: Segmentation fault (thread 140526177928960, pid 11)
Jan 17 16:51:41 kms 89a2a187849b[1160]: Stack trace:
Jan 17 16:52:02 kms 89a2a187849b[1160]: [??]
Jan 17 16:52:02 kms 89a2a187849b[1160]: ??:0
Jan 17 16:52:02 kms 89a2a187849b[1160]: 0xCD1E at /usr/lib/x86_64-linux-gnu/gstreamer-1.5/libgstdtls.so
Jan 17 16:52:02 kms 89a2a187849b[1160]: [__restore_rt]
Jan 17 16:52:02 kms 89a2a187849b[1160]: /lib/x86_64-linux-gnu/libpthread.so.0:0x11390
Jan 17 16:52:03 kms 89a2a187849b[1160]: [??]
Jan 17 16:52:03 kms 89a2a187849b[1160]: ??:0
Jan 17 16:52:03 kms 89a2a187849b[1160]: 0xCD1E at /usr/lib/x86_64-linux-gnu/gstreamer-1.5/libgstdtls.so
Jan 17 16:52:03 kms 89a2a187849b[1160]: [??]
Jan 17 16:52:03 kms 89a2a187849b[1160]: ??:0
Jan 17 16:52:03 kms 89a2a187849b[1160]: 0xEB31 at /usr/lib/x86_64-linux-gnu/gstreamer-1.5/libgstdtls.so
Jan 17 16:52:04 kms 89a2a187849b[1160]: [??]
Jan 17 16:52:04 kms 89a2a187849b[1160]: ??:0
Jan 17 16:52:04 kms 89a2a187849b[1160]: 0x61D2 at /usr/lib/x86_64-linux-gnu/gstreamer-1.5/libgstdtls.so
Jan 17 16:52:04 kms 89a2a187849b[1160]: [??]
Jan 17 16:52:04 kms 89a2a187849b[1160]: ??:0
Jan 17 16:52:04 kms 89a2a187849b[1160]: 0x646A at /usr/lib/x86_64-linux-gnu/gstreamer-1.5/libgstdtls.so
Jan 17 16:52:05 kms 89a2a187849b[1160]: [gst_flow_get_name]
Jan 17 16:52:05 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x6E5CF
Jan 17 16:52:05 kms 89a2a187849b[1160]: [gst_pad_push]
Jan 17 16:52:05 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x76533
Jan 17 16:52:06 kms 89a2a187849b[1160]: [??]
Jan 17 16:52:06 kms 89a2a187849b[1160]: ??:0
Jan 17 16:52:06 kms 89a2a187849b[1160]: 0x953C at /usr/lib/x86_64-linux-gnu/gstreamer-1.5/libgstdtls.so
Jan 17 16:52:06 kms 89a2a187849b[1160]: [gst_flow_get_name]
Jan 17 16:52:06 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x6E5CF
Jan 17 16:52:07 kms 89a2a187849b[1160]: [gst_pad_push]
Jan 17 16:52:07 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x76533
Jan 17 16:52:07 kms 89a2a187849b[1160]: [gst_proxy_pad_chain_default]
Jan 17 16:52:07 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x5F5E3
Jan 17 16:52:08 kms 89a2a187849b[1160]: [gst_flow_get_name]
Jan 17 16:52:08 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x6E5CF
Jan 17 16:52:08 kms 89a2a187849b[1160]: [gst_pad_push]
Jan 17 16:52:08 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x76533
Jan 17 16:52:09 kms 89a2a187849b[1160]: [gst_base_src_wait_playing]
Jan 17 16:52:09 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstbase-1.5.so.0:0x30D75
Jan 17 16:52:09 kms 89a2a187849b[1160]: [gst_tag_setter_get_tag_merge_mode]
Jan 17 16:52:09 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0xA0C5B
Jan 17 16:52:10 kms 89a2a187849b[1160]: [g_thread_pool_new]
Jan 17 16:52:10 kms 89a2a187849b[1160]: /lib/x86_64-linux-gnu/libglib-2.0.so.0:0x715EE
Jan 17 16:52:10 kms 89a2a187849b[1160]:
Jan 17 16:52:10 kms 89a2a187849b[1160]: False positive error reports may follow
Jan 17 16:52:10 kms 89a2a187849b[1160]: For details see https://github.com/google/sanitizers/issues/189
Jan 17 16:52:10 kms 89a2a187849b[1160]: ==902==WARNING: ASan is ignoring requested __asan_handle_no_return: stack top: 0x7fcecceab440; bottom 0x7fd08bec3000; size: 0xfffffffe40fe8440 (-7499512768)
Jan 17 16:52:10 kms 89a2a187849b[1160]: False positive error reports may follow
Jan 17 16:52:10 kms 89a2a187849b[1160]: For details see https://github.com/google/sanitizers/issues/189
Jan 17 16:52:10 kms 89a2a187849b[1160]: /entrypoint.sh: line 74:    11 Aborted                 (core dumped) LD_PRELOAD="$PWD/libasan.so" ASAN_OPTIONS='detect_odr_violation=0 detect_leaks=1 detect_invalid_pointer_pairs=2 strict_string_checks=1 detect_stack_use_after_return=0 check_initialization_order=1 strict_init_order=1' LD_LIBRARY_PATH="$PWD" ./kurento-media-server --modules-path="$PWD" --gst-plugin-path="$PWD"
Jan 17 16:52:10 kms containerd[1141]: time="2020-01-17T16:52:10.993675933Z" level=info msg="shim reaped" id=89a2a187849b3ddae466168f7432d1c6c1ce3f44e1bdc4ada230c20a8a3895e2
Jan 17 16:52:11 kms dockerd[1160]: time="2020-01-17T16:52:11.188010267Z" level=warning msg="89a2a187849b3ddae466168f7432d1c6c1ce3f44e1bdc4ada230c20a8a3895e2 cleanup: failed to unmount IPC: umount /var/lib/docker/containers/89a2a187849b3ddae466168f7432d1c6c1ce3f44e1bdc4ada230c20a8a3895e2/mounts/shm, flags: 0x2: no such file or directory"
Jan 17 16:52:11 kms containerd[1141]: time="2020-01-17T16:52:11.303527456Z" level=info msg="shim containerd-shim started" address="/containerd-shim/moby/89a2a187849b3ddae466168f7432d1c6c1ce3f44e1bdc4ada230c20a8a3895e2/shim.sock" debug=false pid=20335
avssav commented 4 years ago

There is another one segfault whom looks like MediaFlow error

Jan 22 16:00:04 kms 89a2a187849b[1160]: 13:34:50.446961105    12 0x61d004ee2280 INFO             agnosticbin kmsagnosticbin.c:899:input_bin_src_caps_probe:<kmsagnosticbin2-3466> Set input caps: audio/x-opus, rate=(int)48000, channels=(int)2, channel-mapping-family=(int)0, stream-co
unt=(int)1, coupled-count=(int)1, streamheader=(buffer)< 4f707573486561640102000080bb0000000000, 4f707573546167731f0000004753747265616d657220656e636f64656420766f72626973636f6d6d656e740000000001 >
Jan 22 16:00:04 kms 89a2a187849b[1160]: ==12==WARNING: ASan is ignoring requested __asan_handle_no_return: stack top: 0x7f4d7f078440; bottom 0x7f4ec7eb6000; size: 0xfffffffeb71c2440 (-5517859776)
Jan 22 16:00:04 kms 89a2a187849b[1160]: False positive error reports may follow
Jan 22 16:00:04 kms 89a2a187849b[1160]: For details see https://github.com/google/sanitizers/issues/189
Jan 22 16:00:04 kms 89a2a187849b[1160]: 13:34:50.530855709    12 0x61d004ee2280 INFO             agnosticbin kmsagnosticbin.c:774:kms_agnostic_bin2_link_pad:<kmsagnosticbin2-3466> Upstream provided caps: ANY
Jan 22 16:00:04 kms 89a2a187849b[1160]: 13:34:50.532832073    12 0x61d004ee2280 INFO             agnosticbin kmsagnosticbin.c:783:kms_agnostic_bin2_link_pad:<kmsagnosticbin2-3466> Downstream wanted caps: audio/x-opus, channels=(int)[ 1, 2147483647 ], rate=(int)[ 1, 2147483647 ]
Jan 22 16:00:04 kms 89a2a187849b[1160]: Segmentation fault (thread 139970820413184, pid 12)
Jan 22 16:00:04 kms 89a2a187849b[1160]: Stack trace:
Jan 22 16:00:08 kms 89a2a187849b[1160]: [std::strstream::str()]
Jan 22 16:00:08 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libstdc++.so.6:0xBCF2A
Jan 22 16:00:09 kms 89a2a187849b[1160]: [__restore_rt]
Jan 22 16:00:09 kms 89a2a187849b[1160]: /lib/x86_64-linux-gnu/libpthread.so.0:0x11390
Jan 22 16:00:09 kms 89a2a187849b[1160]: [std::strstream::str()]
Jan 22 16:00:09 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libstdc++.so.6:0xBCF2A
Jan 22 16:00:09 kms 89a2a187849b[1160]: [std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_get_insert_unique_pos(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)]
Jan 22 16:00:09 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libkmscoreimpl.so.6:0x10DA33
Jan 22 16:00:10 kms 89a2a187849b[1160]: [std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_get_insert_hint_unique_pos(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)]
Jan 22 16:00:10 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libkmscoreimpl.so.6:0x10DB16
Jan 22 16:00:10 kms 89a2a187849b[1160]: [std::_Rb_tree_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > > >::_M_emplace_hint_unique<std::piecewise_construct_t const&, std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>, std::tuple<> >(std::_Rb_tree_const_iterator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<kurento::MediaFlowState> > >, std::piecewise_construct_t const&, std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&>&&, std::tuple<>&&)]
Jan 22 16:00:10 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libkmscoreimpl.so.6:0x10DC12
Jan 22 16:00:11 kms 89a2a187849b[1160]: [kurento::MediaElementImpl::mediaFlowOutStateChange(int, char*, KmsElementPadType)]
Jan 22 16:00:11 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libkmscoreimpl.so.6:0x101EC8
Jan 22 16:00:11 kms 89a2a187849b[1160]: [virtual thunk to kurento::MediaElementImpl::getGstreamerDot(std::shared_ptr<kurento::GstreamerDotDetails>)]
Jan 22 16:00:11 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libkmscoreimpl.so.6:0xFBCE9
Jan 22 16:00:11 kms 89a2a187849b[1160]: [g_closure_invoke]
Jan 22 16:00:11 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0:0xFEFF
Jan 22 16:00:12 kms 89a2a187849b[1160]: [g_signal_handler_disconnect]
Jan 22 16:00:12 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0:0x21FC1
Jan 22 16:00:12 kms 89a2a187849b[1160]: [g_signal_emit_valist]
Jan 22 16:00:12 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0:0x2AD5C
Jan 22 16:00:13 kms 89a2a187849b[1160]: [g_signal_emit]
Jan 22 16:00:13 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0:0x2B08F
Jan 22 16:00:13 kms 89a2a187849b[1160]: [check_if_flow_media]
Jan 22 16:00:13 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libkmsgstcommons.so.6:0x1FBE4
Jan 22 16:00:13 kms 89a2a187849b[1160]: [gst_mini_object_steal_qdata]
Jan 22 16:00:13 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x6C29B
Jan 22 16:00:14 kms 89a2a187849b[1160]: [g_hook_list_marshal]
Jan 22 16:00:14 kms 89a2a187849b[1160]: /lib/x86_64-linux-gnu/libglib-2.0.so.0:0x3A904
Jan 22 16:00:14 kms 89a2a187849b[1160]: [gst_mini_object_steal_qdata]
Jan 22 16:00:14 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x6AAFB
Jan 22 16:00:15 kms 89a2a187849b[1160]: [gst_flow_get_name]
Jan 22 16:00:15 kms 89a2a187849b[1160]: /usr/lib/x86_64-linux-gnu/libgstreamer-1.5.so.0:0x6E98B
Jan 22 16:00:15 kms 89a2a187849b[1160]:
Jan 22 16:00:15 kms 89a2a187849b[1160]: False positive error reports may follow
Jan 22 16:00:15 kms 89a2a187849b[1160]: For details see https://github.com/google/sanitizers/issues/189
Jan 22 16:00:15 kms 89a2a187849b[1160]: /entrypoint.sh: line 74:    12 Aborted                 (core dumped) LD_PRELOAD="$PWD/libasan.so" ASAN_OPTIONS='detect_odr_violation=0 detect_leaks=1 detect_invalid_pointer_pairs=2 strict_string_checks=1 detect_stack_use_after_return=0 check_initialization_order=1 strict_init_order=1' LD_LIBRARY_PATH="$PWD" ./kurento-media-server --modules-path="$PWD" --gst-plugin-path="$PWD"
Jan 22 16:00:15 kms containerd[1141]: time="2020-01-22T16:00:15.656821459Z" level=info msg="shim reaped" id=89a2a187849b3ddae466168f7432d1c6c1ce3f44e1bdc4ada230c20a8a3895e2
Jan 22 16:00:15 kms dockerd[1160]: time="2020-01-22T16:00:15.835475996Z" level=warning msg="89a2a187849b3ddae466168f7432d1c6c1ce3f44e1bdc4ada230c20a8a3895e2 cleanup: failed to unmount IPC: umount /var/lib/docker/containers/89a2a187849b3ddae466168f7432d1c6c1ce3f44e1bdc4ada230c20a8a3895e2/mounts/shm, flags: 0x2: no such file or directory"
Jan 22 16:00:15 kms containerd[1141]: time="2020-01-22T16:00:15.953646910Z" level=info msg="shim containerd-shim started" address="/containerd-shim/moby/89a2a187849b3ddae466168f7432d1c6c1ce3f44e1bdc4ada230c20a8a3895e2/shim.sock" debug=false pid=23132
j1elo commented 4 years ago

Surely that looks problematic... Anyhow, I'm now working on a better Docker container, that includes debug symbols so when there is a stack trace, it tells us information about file name and line number where the segmentation fault happened. That way, we can go directly to the offending file and inspect the code. I'll let you know when this new image is available for use.

I haven't been able to reproduce the issue, but I'll leave it testing overnight to see if we catch this one.

nithinpgit commented 4 years ago

Hi In our webinar application after 200 attendees some time kurento media server show 100% cpu spike and it never reset until all user left from the session. we need to kill the kurento process to release cpu usage. average cpu will be 40% to 50 % at a sudden cpu spike to 100% and stay on. it is usually happen when presenter turn on mic and all the participant try to subscribe or if presenter start a mp4 video playback via kurento playerendpoint to 200 users. server is ubuntu 16 , 16 core machine from aws. kurento version 6.13.0 Following error frequently logged (kurento-media-server:2015): GStreamer-CRITICAL **: Element rtpbin0 already has a pad named send_rtp_sink_0, the behaviour of gst_element_get_request_pad() for existing pads is undefined!

j1elo commented 4 years ago

The error

GStreamer-CRITICAL **: Element rtpbin1 already has a pad named recv_rtp_sink_1

that could be seen in Kurento logs was (most of the time) due to mistakenly adding more than 1 video and/or 1 audio media stream track to the RTCPeerConection object in the Javascript side of the application. This would try to negotiate multiple videos or audios, and cause critical warnings inside the GStreamer code in KMS.

Of course if KMS is not able to handle multiple media tracks, it should reject the medias in the SDP negotiation, not crash or cause internal GStreamer-CRITICAL warnings. That bug was solved with commit https://github.com/Kurento/kms-core/commit/6a47630cba2aba4c74527f9757b705c342da5106, available since Kurento 6.13.1. Upgrade instructions can be found here: Local Upgrade

Please reopen if this issue is still happening with latest versions of KMS.