Bug 136074 – GStreamer-CRITICAL **: gst_structure_id_get: assertion 'first_field_id != 0' failed

• Status: RESOLVED
• Resolution: DUPLICATE
• Component: Media

[Michael Catanzaro]

When loading http://www.vox.com/2014/8/18/6043763/cnns-jake-tapper-on-the-police-in-ferguson-this-doesnt-make-any-sense I see the following critical warning repeated dozens of times:

(WebKitWebProcess:6706): GStreamer-CRITICAL **: gst_structure_id_get: assertion 'first_field_id != 0' failed

Nothing happens when I click Play on the video.

[Michael Catanzaro]

Here's a release build backtrace with G_DEBUG=fatal-criticals.  I can get one from a debug build if you think it'd be helpful.

#0  g_logv (log_domain=0x7fd3bd91c213 <g_log_domain_gstreamer> "GStreamer", 
    log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>, 
    args=args@entry=0x7fff30777708) at gmessages.c:1046
        domain = 0x0
        data = 0x0
        depth = 0
        log_func = 0x7fd3bd882ba0 <debug_log_handler>
        domain_fatal_mask = <optimized out>
        masquerade_fatal = <optimized out>
        test_level = <optimized out>
        was_fatal = <optimized out>
        was_recursion = <optimized out>
        msg = 0x2d0a9e0 "gst_structure_id_get: assertion 'first_field_id != 0' failed"
        msg_alloc = 0x2d0a9e0 "gst_structure_id_get: assertion 'first_field_id != 0' failed"
        i = 3
#1  0x00007fd3c0b7fe12 in g_log (log_domain=<optimized out>, 
    log_level=log_level@entry=G_LOG_LEVEL_CRITICAL, 
    format=format@entry=0x7fd3c0be51d7 "%s: assertion '%s' failed")
    at gmessages.c:1079
        args = {{gp_offset = 40, fp_offset = 48, 
            overflow_arg_area = 0x7fff307777e0, 
            reg_save_area = 0x7fff30777720}}
#2  0x00007fd3c0b7fe39 in g_return_if_fail_warning (
    log_domain=<optimized out>, 
    pretty_function=pretty_function@entry=0x7fd3bd9303d0 <__func__.20699> "gst_structure_id_get", 
    expression=expression@entry=0x7fd3bd916448 "first_field_id != 0")
    at gmessages.c:1088
No locals.
#3  0x00007fd3bd8e6cba in gst_structure_id_get (structure=<optimized out>, 
    first_field_id=<optimized out>) at gststructure.c:3066
        args = {{gp_offset = 3178951544, fp_offset = 32723, 
            overflow_arg_area = 0x0, 
            reg_save_area = 0x7fd3bd7af390 <_GLOBAL_OFFSET_TABLE_+176>}}
        __func__ = "gst_structure_id_get"
#4  0x00007fd3bd795cd6 in gst_message_parse_mpegts_section (
    message=0x7fd3c231d760 <main_arena>) at gstmpegtssection.c:256
        st = 0x1b30f20
        section = 0x7fd3c4e906f0
#5  0x00007fd3c3e44b05 in WebCore::MediaPlayerPrivateGStreamer::handleMessage(_GstMessage*) ()
   from /home/mcatanzaro/jhbuild/install/lib/libwebkit2gtk-4.0.so.37
No symbol table info available.
#6  0x00007fd3c4cc7cf0 in g_cclosure_marshal_VOID__BOXEDv (closure=0x21cfaa0, 
    return_value=<optimized out>, instance=<optimized out>, 
    args=<optimized out>, marshal_data=<optimized out>, 
    n_params=<optimized out>, param_types=0x20ae3d0) at gmarshal.c:1160
        cc = 0x21cfaa0
        data1 = <optimized out>
        data2 = <optimized out>
        callback = <optimized out>
        arg0 = 0x22286a0
        args_copy = {{gp_offset = 32, fp_offset = 48, 
            overflow_arg_area = 0x7fff30777c80, 
            reg_save_area = 0x7fff30777bc0}}
#7  0x00007fd3c4cc5127 in _g_closure_invoke_va (
    closure=closure@entry=0x21cfaa0, return_value=return_value@entry=0x0, 
    instance=instance@entry=0x2191c80, args=args@entry=0x7fff30777ba8, 
    n_params=1, param_types=0x20ae3d0) at gclosure.c:831
        marshal = 0x7fd3c4cc7c60 <g_cclosure_marshal_VOID__BOXEDv>
        marshal_data = 0x0
        in_marshal = 0
        real_closure = 0x21cfa80
        __FUNCTION__ = "_g_closure_invoke_va"
#8  0x00007fd3c4cde0ec in g_signal_emit_valist (instance=0x2191c80, 
    signal_id=<optimized out>, detail=1698, 
    var_args=var_args@entry=0x7fff30777ba8) at gsignal.c:3218
        return_accu = 0x0
        accu = {g_type = 0, data = {{v_int = 0, v_uint = 0, v_long = 0, 
              v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, 
              v_double = 0, v_pointer = 0x0}, {v_int = 0, v_uint = 0, 
              v_long = 0, v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, 
              v_double = 0, v_pointer = 0x0}}}
        accumulator = 0x0
        emission = {next = 0x0, instance = 0x2191c80, ihint = {
            signal_id = 212, detail = 1698, run_type = G_SIGNAL_RUN_FIRST}, 
          state = EMISSION_RUN, chain_type = 34266576}
        signal_id = <optimized out>
        instance_type = 34266576
        emission_return = {g_type = 0, data = {{v_int = 0, v_uint = 0, 
              v_long = 0, v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, 
              v_double = 0, v_pointer = 0x0}, {v_int = 0, v_uint = 0, 
              v_long = 0, v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, 
              v_double = 0, v_pointer = 0x0}}}
        rtype = 4
        static_scope = 0
        fastpath_handler = <optimized out>
        closure = 0x21cfaa0
        run_type = <optimized out>
        l = <optimized out>
        fastpath = <optimized out>
        instance_and_params = <optimized out>
        signal_return_type = <optimized out>
        param_values = <optimized out>
        i = <optimized out>
        n_params = <optimized out>
        __FUNCTION__ = "g_signal_emit_valist"
#9  0x00007fd3c4cded72 in g_signal_emit (instance=instance@entry=0x2191c80, 
    signal_id=<optimized out>, detail=<optimized out>) at gsignal.c:3365
        var_args = {{gp_offset = 24, fp_offset = 48, 
            overflow_arg_area = 0x7fff30777c80, 
            reg_save_area = 0x7fff30777bc0}}
#10 0x00007fd3bd895ff2 in gst_bus_async_signal_func (bus=0x2191c80, 
    message=0x22286a0, data=<optimized out>) at gstbus.c:1131
        detail = <optimized out>
#11 0x00007fd3bd896d41 in gst_bus_source_dispatch (source=0x21d1f90, 
    callback=0x7fd3bd895f70 <gst_bus_async_signal_func>, user_data=0x0)
    at gstbus.c:775
        handler = <optimized out>
        bsource = 0x21d1f90
        message = 0x22286a0
        keep = <optimized out>
        bus = 0x2191c80
        __func__ = "gst_bus_source_dispatch"
        __PRETTY_FUNCTION__ = "gst_bus_source_dispatch"
#12 0x00007fd3c0b78e1a in g_main_dispatch (context=0x19c57c0) at gmain.c:3064
        dispatch = 0x7fd3bd896c50 <gst_bus_source_dispatch>
        prev_source = 0x0
        was_in_call = 0
        user_data = 0x0
        callback = 0x7fd3bd895f70 <gst_bus_async_signal_func>
        cb_funcs = 0x7fd3c0c65c20 <g_source_callback_funcs>
        cb_data = 0x20aee30
        need_destroy = <optimized out>
        source = 0x21d1f90
        current = 0x1a0c4a0
        i = 0
#13 g_main_context_dispatch (context=context@entry=0x19c57c0) at gmain.c:3663
No locals.
#14 0x00007fd3c0b79138 in g_main_context_iterate (context=0x19c57c0, 
    block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at gmain.c:3734
        max_priority = 120
        timeout = 0
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = 4
        fds = 0x1f53de0
#15 0x00007fd3c0b793fa in g_main_loop_run (loop=0x1f0dbb0) at gmain.c:3928
        __FUNCTION__ = "g_main_loop_run"
#16 0x00007fd3c3215a61 in WebProcessMainUnix ()
   from /home/mcatanzaro/jhbuild/install/lib/libwebkit2gtk-4.0.so.37
No symbol table info available.
#17 0x00007fd3c1f86d65 in __libc_start_main (main=0x400810 <main>, argc=2, 
    argv=0x7fff30777f58, init=<optimized out>, fini=<optimized out>, 
    rtld_fini=<optimized out>, stack_end=0x7fff30777f48) at libc-start.c:285
        result = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {0, -2243833908801446402, 
                4196128, 140734006525776, 0, 0, 2243404064226926078, 
                2268634445224599038}, mask_was_saved = 0}}, priv = {pad = {
              0x0, 0x0, 0x400820 <__libc_csu_init>, 0x7fff30777f58}, data = {
              prev = 0x0, cleanup = 0x0, canceltype = 4196384}}}
        not_first_call = <optimized out>
#18 0x0000000000400749 in _start ()
No symbol table info available.

[Philippe Normand]

CCing Brendan, this bug seems related with the gst mpegts track support

[Brendan Long]

What version of GStreamer are you running? You should be able to tell by running:

gst-launch-1.0 --version

I don't see this problem with the version of GStreamer I was running, so I'm trying the latest git checkout now.

[Michael Catanzaro]

I built gstreamer from git with GNOME jhbuild, commit 63e1f9c8da3870560312c2a0e235e386cef45881.  Looks like the tip of the 1.4 branch from a week ago.

[Philippe Normand]

Also please note that Michael doesn't have the Flash plugin installed.

[Brendan Long]

Hm I don't see this with the latest code either.. :\

[Michael Catanzaro]

:/

I updated to WebKit master and now this page now additionally causes the web process to crash with the following backtrace, which appears to be the same as in bug #136073. (But maybe this is due to a change in that page rather than WebKit.)

Program terminated with signal SIGABRT, Aborted.
#0  0x00007fb277ef2c39 in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56	  return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) bt full
#0  0x00007fb277ef2c39 in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
        resultvar = 0
        pid = 6204
        selftid = 6368
#1  0x00007fb277ef4348 in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x57288, 
            sa_sigaction = 0x57288}, sa_mask = {__val = {140401876967488, 
              34816640, 140404540167974, 140402480906245, 0, 44, 
              140404492877120, 140401876967488, 34816640, 724000, 
              140404540195205, 44, 140404493793277, 140404496759296, 44, 0}}, 
          sa_flags = 2015853056, sa_restorer = 0x7fb276b95df0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007fb276b11735 in g_mutex_unlock_slowpath (mutex=<optimized out>, 
    prev=<optimized out>) at gthread-posix.c:1321
No locals.
#3  0x00007fb276b113ee in g_mutex_unlock (mutex=<optimized out>)
    at gthread-posix.c:1344
        prev = <optimized out>
#4  0x00007fb1c4a798bf in gst_hls_demux_change_playlist (
    demux=demux@entry=0x7fb1dc00a040, max_bitrate=7449114)
    at gsthlsdemux.c:1673
---Type <return> to continue, or q <return> to quit---
        previous_variant = 0x21342a0
        current_variant = 0x2134280
        old_bandwidth = 357000
        new_bandwidth = 724000
        __FUNCTION__ = "gst_hls_demux_change_playlist"
#5  0x00007fb1c4a7d8ad in gst_hls_demux_switch_playlist (demux=0x7fb1dc00a040)
    at gsthlsdemux.c:1755
        bitrate = 9311393
#6  gst_hls_demux_stream_loop (demux=0x7fb1dc00a040) at gsthlsdemux.c:1249
        end_of_playlist = 0
        err = 0x0
        __FUNCTION__ = "gst_hls_demux_stream_loop"
#7  0x00007fb273844346 in gst_task_func (task=0x22bd710) at gsttask.c:317
        lock = 0x7fb1dc00a220
        tself = 0x2773e30
        priv = 0x22bd6c0
        __PRETTY_FUNCTION__ = "gst_task_func"
#8  0x00007fb276af50cc in g_thread_pool_thread_proxy (data=<optimized out>)
    at gthreadpool.c:307
        task = 0x7fb1d8001c70
        pool = 0x26a2a00
#9  0x00007fb276af4745 in g_thread_proxy (data=0x2773e30) at gthread.c:764
        thread = 0x2773e30
---Type <return> to continue, or q <return> to quit---
#10 0x00007fb27626df33 in start_thread (arg=0x7fb2157f8700)
    at pthread_create.c:309
        __res = <optimized out>
        pd = 0x7fb2157f8700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140402841585408, 
                3276817314980143258, 0, 0, 140402841586112, 140402841585408, 
                -3306278733295542118, -3306350550596476774}, 
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, 
            data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
#11 0x00007fb277fb1ded in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
No locals.

[Brendan Long]

Oh so actually completely removing the flash plugin caused me to start getting problems. For me I get this crash at first:

ASSERTION FAILED: !ptr || !g_object_is_floating(G_OBJECT(ptr))
../../Source/WebCore/platform/graphics/gstreamer/GRefPtrGStreamer.cpp(30) : WTF::GRefPtr<T> WTF::adoptGRef(T*) [with T = _GstElement]
1   0x7f5ae3dd162c /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libjavascriptcoregtk-4.0.so.18(WTFCrash+0x1e) [0x7f5ae3dd162c]
2   0x7f5ae9ba6444 /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZN3WTF9adoptGRefI11_GstElementEENS_7GRefPtrIT_EEPS3_+0x58) [0x7f5ae9ba6444]
3   0x7f5ae9bc8c83 /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZN15StreamingClientC1EP13_WebKitWebSrc+0x41) [0x7f5ae9bc8c83]
4   0x7f5ae9bcae34 /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZN29ResourceHandleStreamingClientC2EP13_WebKitWebSrcRKN7WebCore15ResourceRequestE+0x38) [0x7f5ae9bcae34]
5   0x7f5ae9bc742f /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(+0x54fe42f) [0x7f5ae9bc742f]
6   0x7f5ae9bcd26c /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZNSt5_BindIFPFvP13_WebKitWebSrcES1_EE6__callIvIEILm0EEEET_OSt5tupleIIDpT0_EESt12_Index_tupleIIXspT1_EEE+0x46) [0x7f5ae9bcd26c]
7   0x7f5ae9bcd0da /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZNSt5_BindIFPFvP13_WebKitWebSrcES1_EEclIJEvEET0_DpOT_+0x28) [0x7f5ae9bcd0da]
8   0x7f5ae9bccf25 /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZNSt17_Function_handlerIFvvESt5_BindIFPFvP13_WebKitWebSrcES3_EEE9_M_invokeERKSt9_Any_data+0x20) [0x7f5ae9bccf25]
9   0x7f5ae848fd70 /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZNKSt8functionIFvvEEclEv+0x32) [0x7f5ae848fd70]
10  0x7f5ae3e16d5b /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libjavascriptcoregtk-4.0.so.18(_ZN3WTF15GMainLoopSource12voidCallbackEv+0xbf) [0x7f5ae3e16d5b]
11  0x7f5ae3e170cc /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libjavascriptcoregtk-4.0.so.18(_ZN3WTF15GMainLoopSource18voidSourceCallbackEPS0_+0x18) [0x7f5ae3e170cc]
12  0x7f5ae23d3676 /home/blong/workspace/webkit/WebKitBuild/Dependencies/Root/lib64/libglib-2.0.so.0(g_main_context_dispatch+0x146) [0x7f5ae23d3676]
13  0x7f5ae23d39c8 /home/blong/workspace/webkit/WebKitBuild/Dependencies/Root/lib64/libglib-2.0.so.0(+0x479c8) [0x7f5ae23d39c8]
14  0x7f5ae23d3dca /home/blong/workspace/webkit/WebKitBuild/Dependencies/Root/lib64/libglib-2.0.so.0(g_main_loop_run+0x6a) [0x7f5ae23d3dca]
15  0x7f5aea2ed96c /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZN3WTF7RunLoop3runEv+0x42) [0x7f5aea2ed96c]
16  0x7f5ae887e220 /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(_ZN6WebKit16ChildProcessMainINS_10WebProcessENS_14WebProcessMainEEEiiPPc+0x82) [0x7f5ae887e220]
17  0x7f5ae887e08c /home/blong/workspace/webkit/WebKitBuild/Debug/lib/libwebkit2gtk-4.0.so.37(WebProcessMainUnix+0x20) [0x7f5ae887e08c]
18  0x400820 /home/blong/workspace/webkit/WebKitBuild/Debug/bin/WebKitWebProcess(main+0x20) [0x400820]
19  0x32fae21d65 /lib64/libc.so.6(__libc_start_main+0xf5) [0x32fae21d65]
20  0x400739 /home/blong/workspace/webkit/WebKitBuild/Debug/bin/WebKitWebProcess() [0x400739]

I'll track that down and then try to reproduce your issue tomorrow.

[Philippe Normand]

Ah yes this one is familiar, the change triggering the assert was added in bug 115352 which is quite related with adaptive streaming :) But I'm not sure the patch author tried a debug build.

[Brendan Long]

That crash will be fixed by the change in bug #136132. Unfortunately, after that the page still won't load. It seems to lock up so hard that gdb won't let me pause it and get a backtrace..

[Michael Catanzaro]

(In reply to comment #10)
> That crash will be fixed by the change in bug #136132. Unfortunately, after that the page still won't load. It seems to lock up so hard that gdb won't let me pause it and get a backtrace..

Huh. I'm not getting a lockup after applying your fix from that bug, but a different crash. I'm using a debug build this time, though. First I see the original warning, repeated about 50 times:

(WebKitWebProcess:3692): GStreamer-CRITICAL **: gst_structure_id_get: assertion 'first_field_id != 0' failed

Then I see this:

(WebKitWebProcess:3692): GStreamer-CRITICAL **: 
Trying to dispose element appsrc2, but it is in READY instead of the NULL state.
You need to explicitly set elements to the NULL state before
dropping the final reference, to allow them to clean up.
This problem may also be caused by a refcounting bug in the
application or some element.


(WebKitWebProcess:3692): GStreamer-CRITICAL **: 
Trying to dispose element webkitwebsrc0, but it is in READY instead of the NULL state.
You need to explicitly set elements to the NULL state before
dropping the final reference, to allow them to clean up.
This problem may also be caused by a refcounting bug in the
application or some element.

Attempt to unlock mutex that was not locked
Error sending IPC message: Connection reset by peer

[Brendan Long]

:\

I'm in the middle of release build to see if I can make it work that way. My patch shouldn't have changed the refcounting, but I suppose there are pathological cases where it could. I'm going to look through this to see once I can get a build that doesn't lock up.

[Michael Catanzaro]

The warnings about trying to dispose the objects improperly can actually come before the end of gst_structure_id_get() assertions. The crash is the same as in comment #7 and bug #136073.

[Brendan Long]

(In reply to comment #13)
> The warnings about trying to dispose the objects improperly can actually come before the end of gst_structure_id_get() assertions. The crash is the same as in comment #7 and bug #136073.

Yeah, I meant my patch in that other bug might be causing those warnings somehow :\

[Brendan Long]

So that crash is fixed.. Still not getting the same errors messages you did though. Did the video play for you? Clicking on the play button doesn't do anything for me, even in Firefox..

[Michael Catanzaro]

The video does not play for me in Firefox.  (I don't expect it to.)

The page is still crashing for me, even with your fix in bug #136132.  The backtrace is still the one from comment #7 (except the internals of the glib mutexes seem to have changed slightly, which doesn't seem relevant).  I'm not sure that I ever hit the crash in comment #8, though it's great that it's gone.

It might possibly be relevant that I'm on Fedora, with no patent-encumbered gstreamer codecs installed.

[Brendan Long]

I'm also on Fedora (Fedora 20 / x86_64). I'll see if removing -plugins-ugly helps..

[Michael Catanzaro]

No, I'm still crashing even after installing all the gstreamer plugins in rpmfusion. I don't understand what the difference is between our setups. :(  I'm also using x86_64.

[Brendan Long]

(In reply to comment #18)
> No, I'm still crashing even after installing all the gstreamer plugins in rpmfusion. I don't understand what the difference is between our setups. :(  I'm also using x86_64.

There might be something weird about my setup, since I've been working with GStreamer from git a lot. I'm trying to rebuild WebKit in a systemd container but it'll take a little while.

[Michael Catanzaro]

Well surprise, I just read something that looks like it might be relevant:

"starting from GLib 2.42 (the next stable release), the GMutex implementation on Linux has been switched from a pure pthread wrapper to be futex-based. given that we don’t pay any penalty for it, we decided to ensure consistent behaviour, and proper usage of the API. this means that GLib 2.42 will abort if you try to clear an uninitialized or locked GMutex, as well as if you try to unlock an already unlocked one. this ensures that your code will actually be portable, and you’ll catch errors much more quickly." [1]  (The rest of that blog post is irrelevant, no need to check it out.)

So since I'm running epiphany from jhbuild, I am using the new GMutex implementation and whatever process is unlocking that already-unlocked mutex (see it at the bottom of comment #7) is getting killed, whereas for you with glib 2.40 that is harmless and nothing happens and you don't even get an error. I bet if you test in Fedora 21 with glib 2.41.x or in a BSD with any version of glib, you'll get the crash.

P.S. Pretty sure this bug is a duplicate of bug #136073. I'm not sure why this page didn't crash for me originally, but now that it's been crashing with the same stack trace as my report in that bug, there doesn't seem to be any point to keep both bugs open.

[1] http://www.bassi.io/articles/2014/08/27/gdk-and-threads/

[Michael Catanzaro]

(In reply to comment #20)
>  (see it at the bottom of comment #7)

comment #11, sorry.

[Philippe Normand]

Let's close this one then and focus on #136073

*** This bug has been marked as a duplicate of bug 136073 ***