After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 776540 - GstGL: Occasional assertion failures on GST_IS_GL_DISPLAY and GST_IS_GL_CONTEXT
GstGL: Occasional assertion failures on GST_IS_GL_DISPLAY and GST_IS_GL_CONTEXT
Status: RESOLVED OBSOLETE
Product: GStreamer
Classification: Platform
Component: gst-plugins-base
1.10.2
Other Mac OS
: Normal normal
: git master
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2016-12-28 10:52 UTC by Petros
Modified: 2018-11-03 11:53 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
GST_DEBUG=*gl:6 (355.52 KB, text/plain)
2016-12-28 10:52 UTC, Petros
Details
Sync mode with GST_DEBUG=*gl*:6 (126.36 KB, text/plain)
2016-12-30 09:36 UTC, Petros
Details
GST_DEBUG=:*gl*:7 (657.45 KB, text/plain)
2017-01-02 12:16 UTC, Petros
Details
GST_DEBUG=gl*:7,GST_REFCOUNTING:6 (640.39 KB, application/x-gzip)
2017-01-05 08:51 UTC, Petros
Details
Full valgrind log (78.32 KB, application/x-gzip)
2017-01-05 10:40 UTC, Petros
Details
GST_DEBUG=gl*:7,basetransform:5 (3.00 MB, audio/audible)
2017-01-07 09:44 UTC, Petros
Details
GST_DEBUG=gl*:7,basetransform:5 (3.00 MB, application/octet-stream)
2017-01-07 09:45 UTC, Petros
Details
GST_DEBUG=gl*:7,basetransform:5 (3.00 MB, application/octet-stream)
2017-01-07 09:47 UTC, Petros
Details
GST_DEBUG=gl*:7,basetransform:5 (2.76 MB, application/octet-stream)
2017-01-07 09:49 UTC, Petros
Details

Description Petros 2016-12-28 10:52:48 UTC
Created attachment 342522 [details]
GST_DEBUG=*gl:6

I am experiencing some weird behavior related to the GstGL elements when trying to load videos in async mode ( i.e not blocking the pipeline until its pre-rolled ).

More specifically I occasionally get : 

** (<unknown>:65255): CRITICAL **: gst_gl_context_get_display: assertion 'GST_IS_GL_CONTEXT (context)' failed

** (<unknown>:65255): CRITICAL **: gst_gl_display_get_handle_type: assertion 'GST_IS_GL_DISPLAY (display)' failed

(<unknown>:65255): GStreamer-CRITICAL **: gst_object_unref: assertion 'object != NULL' failed

(<unknown>:65255): GStreamer-CRITICAL **: gst_object_unref: assertion 'object != NULL' failed

and / or 

(<unknown>:65255): GStreamer-CRITICAL **: invalid unclassed object pointer for value type 'GstGLDisplay'

These assertion failures show up in a non-consistent way and although the application most of the times will still continue properly there are other times where it will just fail an abort. What is interesting is that if I export GST_DEBUG=*gl:6 to try and observe what is happening the application will fail after some reloads with:

** (<unknown>:64943): CRITICAL **: gst_gl_context_fill_info: assertion 'context->priv->active_thread == g_thread_self ()' failed
**
ERROR:gstglcontext.c:1252:gst_gl_context_create_thread: assertion failed: (error == NULL || *error != NULL)

Attached you can find the log output of such a failure configured with GST_DEBUG=*gl:6.

Again, this does not manifest if I block the pipeline until its pre-rolled .

I ve been seeing this behavior on both OS X and Linux but I m currently testing on OS X.

The player is playbin based and is located here :

https://github.com/PetrosKataras/Cinder/blob/master/src/cinder/linux/GstPlayer.cpp

with the relevant parts of initializing and setting the GL components :

https://github.com/PetrosKataras/Cinder/blob/master/src/cinder/linux/GstPlayer.cpp#L168-L193

https://github.com/PetrosKataras/Cinder/blob/master/src/cinder/linux/GstPlayer.cpp#L465-L503

https://github.com/PetrosKataras/Cinder/blob/master/src/cinder/linux/GstPlayer.cpp#L561-L585

I would really appreciate any clues on this..
Comment 1 Matthew Waters (ystreet00) 2016-12-30 00:48:36 UTC
G_DEBUG=fatal-warnings and a debugger are your friends here with the criticals/warnings.  You can get a backtrace when the critical occurs which may be very helpful.

One possible explanation is a race between cinder/glfw and setting up the GL display/context.  Make sure that the supporting library is set up correctly before attempting to retrieve the necessary display/context from it.

For g(st)_object_(un)ref assertions.  That usually means a refcounting bug somewhere which could be causing this whole mess.

The end of the log has activation happening in another thread than the fill_info is called which should not happen.  Determining why that happens will probably get you closer to fixing the problem:

0:00:09.850171000 0x7fef3e76c840 DEBUG  glcontext gstglcontext.c:726:gst_gl_context_activate:<glcontextcocoa6>[00m activate:1
0:00:09.850246000 0x7fef3d9380a0 DEBUG  glcontext gstglcontext.c:1250:gst_gl_context_create_thread:<glcontextcocoa6>[00m Filling info

** (<unknown>:64943): CRITICAL **: gst_gl_context_fill_info: assertion 'context->priv->active_thread == g_thread_self ()' failed
**
ERROR:gstglcontext.c:1252:gst_gl_context_create_thread: assertion failed: (error == NULL || *error != NULL)
Comment 2 Petros 2016-12-30 09:36:03 UTC
Created attachment 342609 [details]
Sync mode with GST_DEBUG=*gl*:6
Comment 3 Petros 2016-12-30 09:36:44 UTC
Hi Matthew and thank you very much for your reply.

I m fairly sure that the context from Cinder's side is active and valid at the point where I am retrieving it in order to initialize the GstGL side. The context I am retrieving from Cinder is non-null and the same that I get from a straight call to CGLGetCurrentContex() when the fail happens. 

Cinder is using straight Cocoa on OS X and GLFW is used only on Linuxland but I am facing the same issue on both platforms.

What makes me worry is that these issues *do not* manifest if I block the pipeline during load until its pre-rolled. For comparison I attach a log at the same level as the previous one but on sync mode this time ( i.e I m blocking until pre-roll during load ).

I ve realised that for some reason the activation happens in a different thread but I m not entirely sure what would be the best way to debug this issue and figure out why this would be happening. The OS X binaries also seem to miss debug symbols which makes things a bit harder to debug but I could also try on Linux where I m using a manually built gst-uninstalled setup.
Comment 4 Petros 2016-12-30 12:29:01 UTC
I have some more info after running on Linux.

Here is the backtrace :

  • #0 g_logv
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #1 g_log
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #2 gst_gl_context_get_display
    at gstglcontext.c line 1490
  • #3 gst_gl_handle_set_context
    at gstglutils.c line 403
  • #4 gst_gl_base_filter_set_context
    at gstglbasefilter.c line 178
  • #5 _gst_context_query
    at gstglutils.c line 233
  • #6 gst_gl_context_query
    at gstglutils.c line 282
  • #7 gst_gl_ensure_element_data
    at gstglutils.c line 346
  • #8 gst_gl_base_filter_change_state
    at gstglbasefilter.c line 483
  • #9 gst_element_change_state
    at gstelement.c line 2695
  • #10 gst_element_set_state_func
    at gstelement.c line 2649
  • #11 gst_bin_element_set_state
    at gstbin.c line 2613
  • #12 gst_bin_change_state_func
    at gstbin.c line 2955
  • #13 gst_element_change_state
    at gstelement.c line 2695
  • #14 gst_element_set_state_func
    at gstelement.c line 2649
  • #15 activate_sink
    at gstplaybin2.c line 4451
  • #16 activate_group
    at gstplaybin2.c line 5243
  • #17 setup_next_source
    at gstplaybin2.c line 5644
  • #18 gst_play_bin_change_state
    at gstplaybin2.c line 5774
  • #19 gst_element_change_state
    at gstelement.c line 2695
  • #20 gst_element_set_state_func
    at gstelement.c line 2649
  • #21 gst::video::GstPlayer::setPipelineState
    at /home/petroska/Software/libs/cinder-aes/src/cinder/linux/GstPlayer.cpp line 980
  • #22 gst::video::GstPlayer::load
    at /home/petroska/Software/libs/cinder-aes/src/cinder/linux/GstPlayer.cpp line 659
  • #23 cinder::linux::MovieBase::initFromPath
    at /home/petroska/Software/libs/cinder-aes/src/cinder/linux/Movie.cpp line 68
  • #24 cinder::linux::MovieGl::MovieGl
    at /home/petroska/Software/libs/cinder-aes/src/cinder/linux/Movie.cpp line 247
  • #25 cinder::linux::MovieGl::create
    at /home/petroska/Software/libs/cinder-aes/include/cinder/linux/Movie.h line 170
  • #26 GstPlayerTestApp::loadMovieFile
    at /home/petroska/Software/libs/cinder-aes/test/Linux/GstPlayerRefactorTest/src/GstPlayerTestApp.cpp line 293
  • #27 GstPlayerTestApp::newLoad
    at /home/petroska/Software/libs/cinder-aes/test/Linux/GstPlayerRefactorTest/src/GstPlayerTestApp.cpp line 206
  • #28 GstPlayerTestApp::testReload
    at /home/petroska/Software/libs/cinder-aes/test/Linux/GstPlayerRefactorTest/src/GstPlayerTestApp.cpp line 195
  • #29 GstPlayerTestApp::testCurrentCase
    at /home/petroska/Software/libs/cinder-aes/test/Linux/GstPlayerRefactorTest/src/GstPlayerTestApp.cpp line 125
  • #30 GstPlayerTestApp::update
    at /home/petroska/Software/libs/cinder-aes/test/Linux/GstPlayerRefactorTest/src/GstPlayerTestApp.cpp line 244
  • #31 cinder::app::AppBase::privateUpdate__
    at /home/petroska/Software/libs/cinder-aes/src/cinder/app/AppBase.cpp line 232
  • #32 cinder::app::AppImplLinux::run
    at /home/petroska/Software/libs/cinder-aes/src/cinder/app/linux/AppImplLinuxGlfw.cpp line 332
  • #33 cinder::app::AppLinux::launch
    at /home/petroska/Software/libs/cinder-aes/src/cinder/app/linux/AppLinux.cpp line 48
  • #34 cinder::app::AppBase::executeLaunch
    at /home/petroska/Software/libs/cinder-aes/src/cinder/app/AppBase.cpp line 190
  • #35 cinder::app::AppLinux::main<GstPlayerTestApp>(std::shared_ptr<cinder::app::Renderer> const&, char const*, int, char* const*, std::function<void (cinder::app::AppBase::Settings*)> const&)
  • #36 main
    at /home/petroska/Software/libs/cinder-aes/test/Linux/GstPlayerRefactorTest/src/GstPlayerTestApp.cpp line 316

It seems that context_replacement is NULL for some reason when reading the structure as I can see from the following lines but no clue yet why this is the case..

...

398         GstGLDisplay *context_display;
399         GstGLDisplay *element_display;
400
401         if (gst_structure_get (s, "context", GST_GL_TYPE_CONTEXT,
402                 &context_replacement, NULL)) {
403           context_display = gst_gl_context_get_display (context_replacement);
404           element_display = display_replacement ? display_replacement : *display;
405           if (element_display
406               && (gst_gl_display_get_handle_type (element_display) &
407                   gst_gl_display_get_handle_type (context_display)) == 0) {
(gdb) print s
$8 = (const GstStructure *) 0x148ff60
(gdb) print *s
$9 = {type = 18969104, name = 216}
(gdb) print context_replacement 
$10 = (GstGLContext *) 0x0
Comment 5 Petros 2017-01-02 10:20:40 UTC
I ve been looking a bit more into this on Linux. It seems that these failures are consistently coming from the glupload element when trying to set gst.gl.app_context and the element has not reached GST_STATE_READY. 

On successful runs if I manually break at the same point where it fails occasionally ( i.e inside gst_gl_handle_context ) the element has already switched to GST_STATE_READY while on failed runs it is in an async state change mode from NULL to READY ( this is visible also on the bt I previously attached ). 

For comparison here is how the upload element looks on a successful run :

{object = {object = {g_type_instance = {g_class = 0x13f3cc0}, ref_count = 3, qdata = 0x0}, lock = {p = 0x0, i = {0, 0}}, name = 0x13f8340 "upload", parent = 0x13dd0e0, 
    flags = 0, control_bindings = 0x0, control_rate = 100000000, last_sync = 18446744073709551615, _gst_reserved = 0x0}, state_lock = {p = 0x13f8310, i = {0, 0}}, 
  state_cond = {p = 0x0, i = {2, 0}}, state_cookie = 1, target_state = GST_STATE_READY, current_state = GST_STATE_READY, next_state = GST_STATE_VOID_PENDING, 
  pending_state = GST_STATE_VOID_PENDING, last_return = GST_STATE_CHANGE_SUCCESS, bus = 0x1270c70, clock = 0x0, base_time = 0, start_time = 0, numpads = 2, pads = 0x13f5480, 
  numsrcpads = 1, srcpads = 0x13f54a0, numsinkpads = 1, sinkpads = 0x13f5460, pads_cookie = 2, contexts = 0x1401020, _gst_reserved = {0x0, 0x0, 0x0}}


and here is how it looks on a failed run :

{object = {object = {g_type_instance = {g_class = 0x13f3cc0}, ref_count = 2, qdata = 0x0}, lock = {p = 0x0, i = {0, 0}}, name = 0x142b2a0 "upload", 
    parent = 0x7fff800126a0, flags = 0, control_bindings = 0x0, control_rate = 100000000, last_sync = 18446744073709551615, _gst_reserved = 0x0}, state_lock = {
    p = 0x1465830, i = {0, 0}}, state_cond = {p = 0x0, i = {1, 0}}, state_cookie = 1, target_state = GST_STATE_READY, current_state = GST_STATE_NULL, 
  next_state = GST_STATE_READY, pending_state = GST_STATE_READY, last_return = GST_STATE_CHANGE_ASYNC, bus = 0x7fffd004d310, clock = 0x0, base_time = 0, start_time = 0, 
  numpads = 2, pads = 0x7fffd01bc620, numsrcpads = 1, srcpads = 0x7fff8c008900, numsinkpads = 1, sinkpads = 0x7fffdc045180, pads_cookie = 2, contexts = 0x7fffd814eba0, 
  _gst_reserved = {0x0, 0x0, 0x0}}


The failure happens at the point where playbin has reached GST_STATE_READY and tries to activate the video-sink that contains the glupload element.

Here is how the video-sink looks at the point of the failure :

{object = {object = {g_type_instance = {g_class = 0x12242c0}, ref_count = 4, qdata = 0x0}, lock = {p = 0x0, i = {0, 0}}, name = 0x1457eb0 "cinder-vbin", parent = 0x0, 
    flags = 32, control_bindings = 0x0, control_rate = 100000000, last_sync = 18446744073709551615, _gst_reserved = 0x0}, state_lock = {p = 0x145f510, i = {0, 0}}, 
  state_cond = {p = 0x0, i = {1, 0}}, state_cookie = 1, target_state = GST_STATE_READY, current_state = GST_STATE_NULL, next_state = GST_STATE_READY, 
  pending_state = GST_STATE_READY, last_return = GST_STATE_CHANGE_ASYNC, bus = 0x7fffd01513b0, clock = 0x0, base_time = 0, start_time = 0, numpads = 1, 
  pads = 0x7fffdc03a400, numsrcpads = 0, srcpads = 0x0, numsinkpads = 1, sinkpads = 0x7fffdc0054c0, pads_cookie = 1, contexts = 0x7fff8c005920, _gst_reserved = {0x0, 0x0, 
    0x0}}

and how playbin looks at the same point :

{parent = {bin = {element = {object = {object = {g_type_instance = {g_class = 0x12971f0}, ref_count = 2, qdata = 0x2}, lock = {p = 0x0, i = {0, 0}}, 
          name = 0x142be00 "playbinsink", parent = 0x0, flags = 32, control_bindings = 0x0, control_rate = 100000000, last_sync = 18446744073709551615, _gst_reserved = 0x0}, 
        state_lock = {p = 0x14645e0, i = {0, 0}}, state_cond = {p = 0x0, i = {3, 0}}, state_cookie = 2, target_state = GST_STATE_PAUSED, current_state = GST_STATE_READY, 
        next_state = GST_STATE_PAUSED, pending_state = GST_STATE_PAUSED, last_return = GST_STATE_CHANGE_ASYNC, bus = 0x7fffcc75e480, clock = 0x0, base_time = 0, 
        start_time = 0, numpads = 0, pads = 0x0, numsrcpads = 0, srcpads = 0x0, numsinkpads = 0, sinkpads = 0x0, pads_cookie = 0, contexts = 0x0, _gst_reserved = {0x0, 0x0, 
          0x0}}, numchildren = 1, children = 0x7fff8c018800, children_cookie = 1, child_bus = 0x7fff8c117b90, messages = 0x7fffdc0d24e0, polling = 0, state_dirty = 0, 
      clock_dirty = 0, provided_clock = 0x0, clock_provider = 0x0, priv = 0x124d620, _gst_reserved = {0x0, 0x0, 0x0, 0x0}}, fixed_clock = 0x0, stream_time = 0, delay = 0, 
    priv = 0x124d600, _gst_reserved = {0x0, 0x0, 0x0, 0x0}}, lock = {p = 0x14454a0, i = {0, 0}}, groups = {{playbin = 0x124d640, lock = {p = 0x0, i = {0, 0}}, valid = 0, 
      active = 0, uri = 0x0, suburi = 0x0, streaminfo = 0x0, source = 0x0, video_channels = 0x7fffdc024a40, audio_channels = 0x7fff8c0030c0, text_channels = 0x7fff8c00d2e0, 
      audio_sink = 0x0, video_sink = 0x0, text_sink = 0x0, uridecodebin = 0x0, suburidecodebin = 0x0, pending = 0, sub_pending = 0, have_group_id = 0, group_id = 0, 
      pad_added_id = 0, pad_removed_id = 0, no_more_pads_id = 0, notify_source_id = 0, drained_id = 0, autoplug_factories_id = 0, autoplug_select_id = 0, 
      autoplug_continue_id = 0, autoplug_query_id = 0, sub_pad_added_id = 0, sub_pad_removed_id = 0, sub_no_more_pads_id = 0, sub_autoplug_continue_id = 0, 
      sub_autoplug_query_id = 0, block_id = 0, stream_changed_pending_lock = {p = 0x0, i = {0, 0}}, stream_changed_pending = 0, suburi_flushes_to_drop_lock = {p = 0x0, i = {
          0, 0}}, suburi_flushes_to_drop = 0x0, pending_buffering_msg = 0x0, combiner = {{media_list = {0x7fffea849a41 "audio/", 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, 
          get_media_caps = 0x0, type = GST_PLAY_SINK_TYPE_AUDIO, combiner = 0x0, channels = 0x7fff8c0030c0, srcpad = 0x0, sinkpad = 0x0, block_id = 0, has_active_pad = 0, 
          has_always_ok = 0, has_tags = 0}, {media_list = {0x7fffea849a2e "video/", 0x7fffea84f94e "image/", 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, get_media_caps = 0x0, 
          type = GST_PLAY_SINK_TYPE_VIDEO, combiner = 0x0, channels = 0x7fffdc024a40, srcpad = 0x0, sinkpad = 0x0, block_id = 0, has_active_pad = 0, has_always_ok = 0, 
          has_tags = 0}, {media_list = {0x7fffea84f955 "text/", 0x7fffea850584 "application/x-subtitle", 0x7fffea85059b "application/x-ssa", 
            0x7fffea8505ad "application/x-ass", 0x7fffea8505bf "subpicture/x-dvd", 0x7fffea84f95b "subpicture/", 0x7fffea8505d0 "subtitle/", 0x0}, 
          get_media_caps = 0x7fffea841ef0 <gst_subtitle_overlay_create_factory_caps>, type = GST_PLAY_SINK_TYPE_TEXT, combiner = 0x0, channels = 0x7fff8c00d2e0, 
          srcpad = 0x0, sinkpad = 0x0, block_id = 0, has_active_pad = 0, has_always_ok = 0, has_tags = 0}}}, {playbin = 0x124d640, lock = {p = 0x1, i = {1, 0}}, valid = 1, 
      active = 0, uri = 0x1246110 "file:///home/petroska/Software/libs/cinder-aes/test/Linux/GstPlayerRefactorTest/assets/bbb.mp4", suburi = 0x0, streaminfo = 0x0, 
      source = 0x0, video_channels = 0x7fffdc02e2a0, audio_channels = 0x7fffd8147240, text_channels = 0x7fff8c004880, audio_sink = 0x0, video_sink = 0x13dd0e0, 
      text_sink = 0x0, uridecodebin = 0x0, suburidecodebin = 0x0, pending = 0, sub_pending = 0, have_group_id = 0, group_id = 0, pad_added_id = 0, pad_removed_id = 0, 
      no_more_pads_id = 0, notify_source_id = 0, drained_id = 0, autoplug_factories_id = 0, autoplug_select_id = 0, autoplug_continue_id = 0, autoplug_query_id = 0, 
      sub_pad_added_id = 0, sub_pad_removed_id = 0, sub_no_more_pads_id = 0, sub_autoplug_continue_id = 0, sub_autoplug_query_id = 0, block_id = 0, 
      stream_changed_pending_lock = {p = 0x0, i = {0, 0}}, stream_changed_pending = 0, suburi_flushes_to_drop_lock = {p = 0x0, i = {0, 0}}, suburi_flushes_to_drop = 0x0, 
      pending_buffering_msg = 0x0, combiner = {{media_list = {0x7fffea849a41 "audio/", 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, get_media_caps = 0x0, 
          type = GST_PLAY_SINK_TYPE_AUDIO, combiner = 0x0, channels = 0x7fffd8147240, srcpad = 0x0, sinkpad = 0x0, block_id = 0, has_active_pad = 0, has_always_ok = 0, 
          has_tags = 0}, {media_list = {0x7fffea849a2e "video/", 0x7fffea84f94e "image/", 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, get_media_caps = 0x0, 
          type = GST_PLAY_SINK_TYPE_VIDEO, combiner = 0x0, channels = 0x7fffdc02e2a0, srcpad = 0x0, sinkpad = 0x0, block_id = 0, has_active_pad = 0, has_always_ok = 0, 
          has_tags = 0}, {media_list = {0x7fffea84f955 "text/", 0x7fffea850584 "application/x-subtitle", 0x7fffea85059b "application/x-ssa", 
            0x7fffea8505ad "application/x-ass", 0x7fffea8505bf "subpicture/x-dvd", 0x7fffea84f95b "subpicture/", 0x7fffea8505d0 "subtitle/", 0x0}, 
          get_media_caps = 0x7fffea841ef0 <gst_subtitle_overlay_create_factory_caps>, type = GST_PLAY_SINK_TYPE_TEXT, combiner = 0x0, channels = 0x7fff8c004880, 
          srcpad = 0x0, sinkpad = 0x0, block_id = 0, has_active_pad = 0, has_always_ok = 0, has_tags = 0}}}}, curr_group = 0x124dac8, next_group = 0x124d808, 
  connection_speed = 0, current_video = -1, current_audio = -1, current_text = -1, buffer_duration = 18446744073709551615, buffer_size = 4294967295, force_aspect_ratio = 1, 
  multiview_mode = GST_VIDEO_MULTIVIEW_FRAME_PACKING_NONE, multiview_flags = GST_VIDEO_MULTIVIEW_FLAGS_NONE, playsink = 0x13da5b0, source = 0x0, dyn_lock = {p = 0x0, i = {0, 
      0}}, shutdown = 0, async_pending = 1, elements_lock = {p = 0x0, i = {0, 0}}, elements_cookie = 0, elements = 0x0, have_selector = 1, video_pending_flush_finish = 0, 
  audio_pending_flush_finish = 0, text_pending_flush_finish = 0, audio_sink = 0x0, video_sink = 0x13dd0e0, text_sink = 0x0, audio_stream_combiner = 0x0, 
  video_stream_combiner = 0x0, text_stream_combiner = 0x0, aelements = 0x0, velements = 0x0, duration = {{valid = 0, format = GST_FORMAT_UNDEFINED, duration = 0}, {
      valid = 0, format = GST_FORMAT_UNDEFINED, duration = 0}, {valid = 0, format = GST_FORMAT_UNDEFINED, duration = 0}, {valid = 0, format = GST_FORMAT_UNDEFINED, 
      duration = 0}, {valid = 0, format = GST_FORMAT_UNDEFINED, duration = 0}}, ring_buffer_max_size = 0, contexts = 0x125b2e0}
Comment 6 Matthew Waters (ystreet00) 2017-01-02 11:02:07 UTC
This may all be because checkBusMessages() at https://github.com/PetrosKataras/Cinder/blob/master/src/cinder/linux/GstPlayer.cpp#L125 is only responding to the async bus handler.  To be able to correctly and non-racily respond to need-context messages, you need to add a sync bus handler for (at the very least) the need-context message.

The two options for that are using:
1. gst_bus_set_sync_handler(), or;
2. gst_bus_enable_sync_message_emission() and the 'sync-message' signal on the bus (https://gstreamer.freedesktop.org/data/doc/gstreamer/head/gstreamer/html/GstBus.html#GstBus-sync-message)

Does adding the synchronous bus handler for the 'need-context' message help the situation?
Comment 7 Petros 2017-01-02 11:09:44 UTC
Hi Matthew,

I tried last week to hook a sync-bus handler only for the need-context message on OS X but I was still getting some issues. It was a very quick test though and in parallel I also had the async bus handler running which I am not sure if this could cause some issues ( although I was not checking anymore inside the async handler for the need-context msg just the state change logic ) . 

Do you think it would worth trying replacing the whole async bus handling with a sync version??

In any case I will give a try on Linux with a sync bus handler and report back.
Comment 8 Matthew Waters (ystreet00) 2017-01-02 11:13:07 UTC
You need both the async and sync handlers.  The need-context should be in the sync handler, everything else there can be async.
Comment 9 Petros 2017-01-02 11:43:02 UTC
So adding gst_bus_sync_handler for handling the need-context msg definitely helps for the state change issue but I got a different one now unfortunately..

(GstPlayerTestApp:29020): GStreamer-CRITICAL **: gst_object_ref: assertion 'object != NULL' failed

Thread 4253 "vqueue:src" received signal SIGTRAP, Trace/breakpoint trap.

Thread 140737010198272 (LWP 816)

  • #0 g_logv
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #1 g_log
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #2 gst_object_ref
    at gstobject.c line 245
  • #3 gst_gl_buffer_pool_new
    at gstglbufferpool.c line 302
  • #4 _gl_memory_upload_propose_allocation
    at gstglupload.c line 363
  • #5 gst_gl_upload_propose_allocation
    at gstglupload.c line 1352
  • #6 _gst_gl_upload_element_propose_allocation
    at gstgluploadelement.c line 181
  • #7 gst_base_transform_default_query
    at gstbasetransform.c line 1538
  • #8 gst_gl_base_filter_query
    at gstglbasefilter.c line 287
  • #9 gst_pad_query
    at gstpad.c line 3950
  • #10 gst_pad_peer_query
    at gstpad.c line 4082
  • #11 gst_base_transform_default_propose_allocation
    at gstbasetransform.c line 1438
  • #12 gst_base_transform_default_query
    at gstbasetransform.c line 1538
  • #13 gst_pad_query
    at gstpad.c line 3950
  • #14 gst_pad_peer_query
    at gstpad.c line 4082
  • #15 query_forward_func
    at gstpad.c line 3318
  • #16 gst_pad_forward
    at gstpad.c line 2947
  • #17 gst_pad_query_default
    at gstpad.c line 3385
  • #18 gst_pad_query
    at gstpad.c line 3950
  • #19 gst_pad_peer_query
    at gstpad.c line 4082
  • #20 query_forward_func
    at gstpad.c line 3318
  • #21 gst_pad_forward
    at gstpad.c line 2947
  • #22 gst_pad_query_default
    at gstpad.c line 3385
  • #23 gst_pad_query
    at gstpad.c line 3950
  • #24 gst_pad_peer_query
    at gstpad.c line 4082
  • #25 gst_base_transform_default_propose_allocation
    at gstbasetransform.c line 1438
  • #26 gst_video_filter_propose_allocation
    at gstvideofilter.c line 64
  • #27 gst_base_transform_default_query
    at gstbasetransform.c line 1538
  • #28 gst_pad_query
    at gstpad.c line 3950
  • #29 gst_pad_peer_query
    at gstpad.c line 4082
  • #30 gst_base_transform_default_propose_allocation
    at gstbasetransform.c line 1438
  • #31 gst_video_filter_propose_allocation
    at gstvideofilter.c line 64
  • #32 gst_base_transform_default_query
    at gstbasetransform.c line 1538
  • #33 gst_pad_query
    at gstpad.c line 3950
  • #34 gst_pad_peer_query
    at gstpad.c line 4082
  • #35 gst_base_transform_default_propose_allocation
    at gstbasetransform.c line 1438
  • #36 gst_video_filter_propose_allocation
    at gstvideofilter.c line 64
  • #37 gst_base_transform_default_query
    at gstbasetransform.c line 1538
  • #38 gst_pad_query
    at gstpad.c line 3950
  • #39 gst_pad_peer_query
    at gstpad.c line 4082
  • #40 gst_base_transform_default_propose_allocation
    at gstbasetransform.c line 1438
  • #41 gst_video_filter_propose_allocation
    at gstvideofilter.c line 64
  • #42 gst_base_transform_default_query
    at gstbasetransform.c line 1538
  • #43 gst_pad_query
    at gstpad.c line 3950
  • #44 gst_pad_peer_query
    at gstpad.c line 4082
  • #45 query_forward_func
    at gstpad.c line 3318
  • #46 gst_pad_forward
    at gstpad.c line 2947
  • #47 gst_pad_query_default
    at gstpad.c line 3385
  • #48 gst_play_sink_convert_bin_query
    at gstplaysinkconvertbin.c line 525
  • #49 gst_pad_query
    at gstpad.c line 3950
  • #50 gst_pad_peer_query
    at gstpad.c line 4082
  • #51 gst_queue_push_one
    at gstqueue.c line 1443
  • #52 gst_queue_loop
    at gstqueue.c line 1506
  • #53 gst_task_func
    at gsttask.c line 334
  • #54 ??
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #55 ??
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #56 start_thread
    at pthread_create.c line 333
  • #57 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 109

Just a not that I m stretching the player to reproduce these issues ( i.e I m reloading  constantly between every 0.1 - 0.3 seconds ).
Comment 10 Matthew Waters (ystreet00) 2017-01-02 11:51:17 UTC
That may be a race somewhere ;)

That backtrace requires more context in the form of a at least a full (GST_DEBUG=*:7) debug log of the run that failed.
Comment 11 Petros 2017-01-02 12:07:00 UTC
This seems pretty difficult to reproduce with GST_DEBUG=*:7 even if I trigger reloads evert 0.05 of a second which could I suppose indicate a racing issue that does not manifest that easily in this case due to logging delays.. ??

Any tricks/ideas to force it somehow??
Comment 12 Petros 2017-01-02 12:16:30 UTC
Created attachment 342712 [details]
GST_DEBUG=:*gl*:7
Comment 13 Petros 2017-01-02 12:17:02 UTC
Managed to reproduce it with GST_DEBUG=*gl*:7
Comment 14 Matthew Waters (ystreet00) 2017-01-05 07:07:03 UTC
This is a refcount bug, gl*:7 isn't enough for them.  We need at least a GST_DEBUG=gl*:7, GST_REFCOUNTING:7 log

As for tricks, try different computers, add small sleeps everywhere around the problematic code (pretty much any function mentioned before everything's destroyed in the log above).

Question, does it happen if you make the time between reloads longer? i.e. a second or two.  This might be a race between startup and shutdown.
Comment 15 Petros 2017-01-05 08:51:15 UTC
Created attachment 342928 [details]
GST_DEBUG=gl*:7,GST_REFCOUNTING:6
Comment 16 Petros 2017-01-05 08:53:08 UTC
It seems really difficult to reproduce it with verbose logging. So far I managed to reproduce only with GST_REFCOUNTING=6. See attachment. I will keep trying to get a more verbose output.

If I trigger reloads between 1.0 - 2.0 seconds it doesn't seem to manifest.. At least the last 20mins that I have it running..
Comment 17 Matthew Waters (ystreet00) 2017-01-05 09:17:13 UTC
Right, so very much pointing to a start/stop race then.

I don't think the extra GST_REFCOUNTING level is going to help much then without context of other debug categories.  We are going to to have to look at other categories.  Try with gl*:7,basetransform:5.  At this point it's very much a guess and check game trying to find a category that will reproduce the race easily enough that also provides enough information to be able to find the cause.
Comment 18 Petros 2017-01-05 09:26:56 UTC
Got something new now with just GST_DEBUG=basetransform:5 

  • #0 g_logv
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #1 g_log
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #2 gst_poll_write_control
    at gstpoll.c line 1658
  • #3 gst_buffer_pool_init
    at gstbufferpool.c line 180
  • #4 g_type_create_instance
    from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
  • #5 ??
    from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
  • #6 g_object_newv
    from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
  • #7 g_object_new
    from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
  • #8 gst_video_buffer_pool_new
    at gstvideopool.c line 283
  • #9 gst_video_decoder_decide_allocation_default
    at gstvideodecoder.c line 3601
  • #10 gst_ffmpegviddec_decide_allocation
    at gstavviddec.c line 1789
  • #11 gst_video_decoder_negotiate_pool
    at gstvideodecoder.c line 3686
  • #12 gst_video_decoder_negotiate_unlocked
    at gstvideodecoder.c line 3835
  • #13 gst_video_decoder_allocate_output_frame
    at gstvideodecoder.c line 3979
  • #14 get_output_buffer
    at gstavviddec.c line 1207
  • #15 gst_ffmpegviddec_video_frame
    at gstavviddec.c line 1393
  • #16 gst_ffmpegviddec_frame
    at gstavviddec.c line 1528
  • #17 gst_ffmpegviddec_handle_frame
    at gstavviddec.c line 1641
  • #18 gst_video_decoder_decode_frame
    at gstvideodecoder.c line 3389
  • #19 gst_video_decoder_chain_forward
    at gstvideodecoder.c line 2131
  • #20 gst_video_decoder_chain
    at gstvideodecoder.c line 2443
  • #21 gst_pad_chain_data_unchecked
    at gstpad.c line 4205
  • #22 gst_pad_push_data
    at gstpad.c line 4457
  • #23 gst_pad_push
    at gstpad.c line 4576
  • #24 gst_base_transform_chain
    at gstbasetransform.c line 2372
  • #25 gst_pad_chain_data_unchecked
    at gstpad.c line 4205
  • #26 gst_pad_push_data
    at gstpad.c line 4457
  • #27 gst_pad_push
    at gstpad.c line 4576
  • #28 gst_base_parse_push_frame
    at gstbaseparse.c line 2543
  • #29 gst_base_parse_handle_and_push_frame
    at gstbaseparse.c line 2360
  • #30 gst_base_parse_finish_frame
    at gstbaseparse.c line 2701
  • #31 gst_h264_parse_handle_frame_packetized
    at gsth264parse.c line 1020
  • #32 gst_h264_parse_handle_frame
    at gsth264parse.c line 1065
  • #33 gst_base_parse_handle_buffer
    at gstbaseparse.c line 2168
  • #34 gst_base_parse_chain
    at gstbaseparse.c line 3240
  • #35 gst_pad_chain_data_unchecked
    at gstpad.c line 4205
  • #36 gst_pad_push_data
    at gstpad.c line 4457
  • #37 gst_pad_push
    at gstpad.c line 4576
  • #38 gst_single_queue_push_one
    at gstmultiqueue.c line 1611
  • #39 gst_multi_queue_loop
    at gstmultiqueue.c line 1923
  • #40 gst_task_func
    at gsttask.c line 334
  • #41 ??
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #42 ??
    from /lib/x86_64-linux-gnu/libglib-2.0.so.0
  • #43 start_thread
    at pthread_create.c line 333
  • #44 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 109

Comment 19 Matthew Waters (ystreet00) 2017-01-05 09:32:06 UTC
That's seemingly unrelated.  Is the code valgrind clean?
Comment 20 Petros 2017-01-05 09:33:36 UTC
Can you suggest a way to run through valgrind without getting false positives?
Comment 21 Matthew Waters (ystreet00) 2017-01-05 09:52:12 UTC
If you just run:

valgrind cmd to run

it will output all occurrences of any read/write to invalid locations.  Chances are extremely slim that any of those are not actual bugs.
Comment 22 Matthew Waters (ystreet00) 2017-01-05 09:52:37 UTC
We're not interested in if memory was leaked or not here.
Comment 23 Petros 2017-01-05 09:58:47 UTC
I had a run with :

G_SLICE=always-malloc
G_DEBUG=gc-friendly

valgrind ./Application

and the only thing it reports is the following during runtime :

Pipeline state changed from : NULL to READY with pending VOID_PENDING
==9989== Thread 23 gstglcontext:
==9989== Conditional jump or move depends on uninitialised value(s)
==9989==    at 0x10DDFFBF: ??? (in /usr/lib/x86_64-linux-gnu/libnvidia-glcore.so.367.35)
==9989==    by 0x10DE0DE8: ??? (in /usr/lib/x86_64-linux-gnu/libnvidia-glcore.so.367.35)
==9989==    by 0x1092AF46: ??? (in /usr/lib/x86_64-linux-gnu/libnvidia-glcore.so.367.35)
==9989==    by 0x70AED34: gst_gl_query_end (gstglquery.c:282)
==9989==    by 0x7090DF5: gst_gl_memory_texsubimage (gstglmemory.c:541)
==9989==    by 0x7093727: _upload_pbo_memory (gstglmemorypbo.c:151)
==9989==    by 0x7093727: _gl_mem_map_gpu_access (gstglmemorypbo.c:338)
==9989==    by 0x7093727: _gl_mem_map (gstglmemorypbo.c:362)
==9989==    by 0x708E135: _map_data_gl (gstglbasememory.c:261)
==9989==    by 0x708BE17: gst_gl_context_thread_add (gstglcontext.c:1537)
==9989==    by 0x708DD7D: _mem_map_full (gstglbasememory.c:295)
==9989==    by 0x66B64DF: gst_memory_map (gstmemory.c:303)
==9989==    by 0x709E400: _do_convert_one_view (gstglcolorconvert.c:2174)
==9989==    by 0x70A0749: _do_convert (gstglcolorconvert.c:2422)
==9989== 
Pipeline state changed from : READY to PAUSED with pending VOID_PENDING
Playing: 0
Pipeline state about to change from : NULL to READY
Pipeline state changed SUCCESSFULLY from : NULL to READY
Pipeline state changed from : NULL to READY with pending VOID_PENDING
Need context gst.gl.GLDisplay from element convert
Need context gst.gl.app_context from element convert
Pipeline state about to change from : READY to PAUSED
Pipeline state change will happen ASYNC from : READY to PAUSED
==9989== Conditional jump or move depends on uninitialised value(s)
==9989==    at 0x10DDFFBF: ??? (in /usr/lib/x86_64-linux-gnu/libnvidia-glcore.so.367.35)
==9989==    by 0x10DE0DE8: ??? (in /usr/lib/x86_64-linux-gnu/libnvidia-glcore.so.367.35)
==9989==    by 0x7090D85: gst_gl_memory_texsubimage (gstglmemory.c:537)
==9989==    by 0x7093727: _upload_pbo_memory (gstglmemorypbo.c:151)
==9989==    by 0x7093727: _gl_mem_map_gpu_access (gstglmemorypbo.c:338)
==9989==    by 0x7093727: _gl_mem_map (gstglmemorypbo.c:362)
==9989==    by 0x708E135: _map_data_gl (gstglbasememory.c:261)
==9989==    by 0x708BE17: gst_gl_context_thread_add (gstglcontext.c:1537)
==9989==    by 0x708DD7D: _mem_map_full (gstglbasememory.c:295)
==9989==    by 0x66B64DF: gst_memory_map (gstmemory.c:303)
==9989==    by 0x709E400: _do_convert_one_view (gstglcolorconvert.c:2174)
==9989==    by 0x70A0749: _do_convert (gstglcolorconvert.c:2422)
==9989==    by 0x70A3D22: _run_message_sync (gstglwindow.c:617)
==9989==    by 0x70A3CC1: _run_message_async (gstglwindow.c:684)
==9989==
Comment 24 Petros 2017-01-05 10:40:09 UTC
Created attachment 342937 [details]
Full valgrind log

Also a full log in case its more helpful.

Configured with:

G_SLICE=always-malloc 
G_DEBUG=gc-friendly 

valgrind -v --leak-check=full --suppressions=./gst.supp
Comment 25 Petros 2017-01-07 09:44:15 UTC
Created attachment 343072 [details]
GST_DEBUG=gl*:7,basetransform:5

part1
Comment 26 Petros 2017-01-07 09:45:33 UTC
Created attachment 343073 [details]
GST_DEBUG=gl*:7,basetransform:5

part2
Comment 27 Petros 2017-01-07 09:47:34 UTC
Created attachment 343074 [details]
GST_DEBUG=gl*:7,basetransform:5

part3
Comment 28 Petros 2017-01-07 09:49:25 UTC
Created attachment 343075 [details]
GST_DEBUG=gl*:7,basetransform:5

part 4
Comment 29 Petros 2017-01-07 09:51:44 UTC
Added some sleep and managed to hit the same issue with GST_DEBUG=gl*:7,basetransform:5. 

I had to split the log since it was too big otherwise so sorry for the multiple attachments.
Comment 30 GStreamer system administrator 2018-11-03 11:53:01 UTC
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/issues/321.