Bug 125411 – [GTK][GStreamer] media/video-preload.html is flakily crashing on WK2

• Component: WebKitGTK
• Status: RESOLVED FIXED

[Zan Dobersek]

The media/video-preload.html layout test seems to crash from time to time.
http://webkit-test-results.appspot.com/dashboards/flakiness_dashboard.html#tests=media%2Fvideo-preload.html

Here's the stderr output from the latest crash:
STDERR: (WebKitWebProcess:26929): GStreamer-CRITICAL **: gst_tag_list_get_string: assertion 'GST_IS_TAG_LIST (list)' failed
STDERR: 
STDERR: (WebKitWebProcess:26929): GStreamer-CRITICAL **: gst_tag_list_get_string: assertion 'GST_IS_TAG_LIST (list)' failed
STDERR: 
STDERR: (WebKitWebProcess:26929): GStreamer-CRITICAL **: gst_mini_object_unref: assertion 'mini_object->refcount > 0' failed

[Zan Dobersek]

media/video-transformed.html as well.
http://webkit-test-results.appspot.com/dashboards/flakiness_dashboard.html#tests=media%2Fvideo-transformed.html

[Alberto Garcia]

I can't reproduce this in my environment, maybe a gstreamer bug?

[Philippe Normand]

Brendan, rings a bell?

[Brendan Long]

Is this GStreamer 0.10 or 1.0?

[Philippe Normand]

1.0, 0.10 is gone for good.

[Brendan Long]

Backtrace:

#0  0x00007fffef6a09d7 in g_slice_alloc () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#1  0x00007fffecc7155f in gst_caps_new_empty () at gstcaps.c:242
#2  0x00007fffecc715f9 in gst_caps_new_any () at gstcaps.c:264
#3  0x00007fffecccbc65 in gst_pad_proxy_query_caps (pad=pad@entry=0x7fff4401a2c0, query=query@entry=0x7fff4003fa30) at gstutils.c:2529
#4  0x00007fffecc9b9c3 in gst_pad_query_caps_default (query=0x7fff4003fa30, pad=0x7fff4401a2c0) at gstpad.c:2859
#5  gst_pad_query_default (pad=0x7fff4401a2c0, parent=<optimized out>, query=0x7fff4003fa30) at gstpad.c:2970
#6  0x00007fffecc9c0ac in gst_pad_query (pad=pad@entry=0x7fff4401a2c0, query=query@entry=0x7fff4003fa30) at gstpad.c:3465
#7  0x00007fffecc9c690 in gst_pad_peer_query (pad=pad@entry=0x7fff4401a780, query=0x7fff4003fa30) at gstpad.c:3596
#8  0x00007fffeccc9698 in query_caps_func (pad=pad@entry=0x7fff4401a780, data=data@entry=0x7fff3e7f9be0) at gstutils.c:2481
#9  0x00007fffecc9b417 in gst_pad_forward (pad=pad@entry=0x2688dd0, forward=forward@entry=0x7fffeccc9680 <query_caps_func>, user_data=user_data@entry=0x7fff3e7f9be0) at gstpad.c:2695
#10 0x00007fffecccbc0a in gst_pad_proxy_query_caps (pad=pad@entry=0x2688dd0, query=query@entry=0x7fff4003fa30) at gstutils.c:2531
#11 0x00007fffecc9b9c3 in gst_pad_query_caps_default (query=0x7fff4003fa30, pad=0x2688dd0) at gstpad.c:2859
#12 gst_pad_query_default (pad=0x2688dd0, parent=<optimized out>, query=0x7fff4003fa30) at gstpad.c:2970
#13 0x00007fffecc9c0ac in gst_pad_query (pad=pad@entry=0x2688dd0, query=query@entry=0x7fff4003fa30) at gstpad.c:3465
#14 0x00007fffecc9c690 in gst_pad_peer_query (pad=pad@entry=0x7fff44063640, query=query@entry=0x7fff4003fa30) at gstpad.c:3596
#15 0x00007fffeccce824 in gst_pad_peer_query_caps (pad=pad@entry=0x7fff44063640, filter=filter@entry=0x0) at gstutils.c:2811
#16 0x00007fff3d781e7e in gst_deinterlace_getcaps (filter=0x7fff4003f9e0, pad=0x7ffefc388f80, self=0x7fff38ac49d0) at gstdeinterlace.c:2145
#17 gst_deinterlace_sink_query (pad=0x7ffefc388f80, parent=<optimized out>, query=0x7fff0c000f70) at gstdeinterlace.c:2649
#18 0x00007fffecc9c0ac in gst_pad_query (pad=pad@entry=0x7ffefc388f80, query=query@entry=0x7fff0c000f70) at gstpad.c:3465
#19 0x00007fffecccc334 in gst_pad_query_caps (pad=pad@entry=0x7ffefc388f80, filter=filter@entry=0x7fff4003f9e0) at gstutils.c:2765
#20 0x00007fffeca0f4dc in gst_base_transform_find_transform (caps=0x7fff4003f990, pad=0x7fff24902b20, trans=0x7fff38037230) at gstbasetransform.c:1124
#21 gst_base_transform_setcaps (trans=trans@entry=0x7fff38037230, pad=0x7fff24902b20, incaps=incaps@entry=0x7fff4003f990) at gstbasetransform.c:1327
#22 0x00007fffeca100eb in gst_base_transform_handle_buffer (trans=trans@entry=0x7fff38037230, inbuf=inbuf@entry=0x7fff4083b4e0, outbuf=outbuf@entry=0x7fff3e7fa2a8) at gstbasetransform.c:1968
#23 0x00007fffeca10b64 in gst_base_transform_chain (pad=<optimized out>, parent=<optimized out>, buffer=0x7fff4083b4e0) at gstbasetransform.c:2201
#24 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff4083b4e0, type=4112, pad=0x7fff24902b20) at gstpad.c:3717
#25 gst_pad_push_data (pad=pad@entry=0x7fff60017240, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff4083b4e0) at gstpad.c:3950
#26 0x00007fffecc9d766 in gst_pad_push (pad=pad@entry=0x7fff60017240, buffer=buffer@entry=0x7fff4083b4e0) at gstpad.c:4053
#27 0x00007fffecc8874b in gst_proxy_pad_chain_default (pad=<optimized out>, parent=<optimized out>, buffer=0x7fff4083b4e0) at gstghostpad.c:128
#28 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff4083b4e0, type=4112, pad=0x24a65b0) at gstpad.c:3717
#29 gst_pad_push_data (pad=pad@entry=0x7fff04862050, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff4083b4e0) at gstpad.c:3950
#30 0x00007fffecc9d766 in gst_pad_push (pad=pad@entry=0x7fff04862050, buffer=buffer@entry=0x7fff4083b4e0) at gstpad.c:4053
#31 0x00007fff7c5e42e3 in gst_stream_synchronizer_sink_chain (pad=0x7fff18023670, parent=<optimized out>, buffer=0x7fff4083b4e0) at gststreamsynchronizer.c:577
#32 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff6006eb50, type=4112, pad=0x7fff18023670) at gstpad.c:3717
#33 gst_pad_push_data (pad=pad@entry=0x7fff60016040, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff6006eb50) at gstpad.c:3950
#34 0x00007fffecc9d766 in gst_pad_push (pad=pad@entry=0x7fff60016040, buffer=buffer@entry=0x7fff6006eb50) at gstpad.c:4053
#35 0x00007fffecc8874b in gst_proxy_pad_chain_default (pad=<optimized out>, parent=<optimized out>, buffer=0x7fff6006eb50) at gstghostpad.c:128
#36 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff6006eb50, type=4112, pad=0x24a6810) at gstpad.c:3717
#37 gst_pad_push_data (pad=0x7fff38ad0070, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff6006eb50) at gstpad.c:3950
#38 0x00007fffecc9d766 in gst_pad_push (pad=<optimized out>, buffer=buffer@entry=0x7fff6006eb50) at gstpad.c:4053
#39 0x00007fff7c37b669 in gst_selector_pad_chain (pad=0x7fff08052480, parent=<optimized out>, buf=0x7fff6006eb50) at gstinputselector.c:1087
#40 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff6006eb50, type=4112, pad=0x7fff08052480) at gstpad.c:3717
#41 gst_pad_push_data (pad=pad@entry=0x7fff4401aea0, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff6006eb50) at gstpad.c:3950
#42 0x00007fffecc9d766 in gst_pad_push (pad=pad@entry=0x7fff4401aea0, buffer=buffer@entry=0x7fff6006eb50) at gstpad.c:4053
#43 0x00007fffecc8874b in gst_proxy_pad_chain_default (pad=<optimized out>, parent=<optimized out>, buffer=0x7fff6006eb50) at gstghostpad.c:128
#44 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff6006eb50, type=4112, pad=0x7fff44067490) at gstpad.c:3717
#45 gst_pad_push_data (pad=pad@entry=0x7fff6401dd10, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff6006eb50) at gstpad.c:3950
#46 0x00007fffecc9d766 in gst_pad_push (pad=pad@entry=0x7fff6401dd10, buffer=buffer@entry=0x7fff6006eb50) at gstpad.c:4053
#47 0x00007fffecc8874b in gst_proxy_pad_chain_default (pad=<optimized out>, parent=<optimized out>, buffer=0x7fff6006eb50) at gstghostpad.c:128
#48 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff6006eb50, type=4112, pad=0x7fff44067250) at gstpad.c:3717
#49 gst_pad_push_data (pad=0x7fff407f7d00, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff6006eb50) at gstpad.c:3950
#50 0x00007fffecc9d766 in gst_pad_push (pad=<optimized out>, buffer=buffer@entry=0x7fff6006eb50) at gstpad.c:4053
#51 0x00007fffebf2a1cf in gst_video_decoder_clip_and_push_buf (decoder=decoder@entry=0x7fff38039b80, buf=buf@entry=0x7fff6006eb50) at gstvideodecoder.c:2585
#52 0x00007fffebf3120d in gst_video_decoder_finish_frame (decoder=0x7fff38039b80, frame=0x0, frame@entry=0x7fff40620690) at gstvideodecoder.c:2500
#53 0x00007fff4a39b9ee in gst_ffmpegviddec_video_frame (ffmpegdec=ffmpegdec@entry=0x7fff38039b80, data=<optimized out>, data@entry=0x7fff3804b460 "", size=<optimized out>, frame=frame@entry=0x7fff64063060, ret=ret@entry=0x7fff3e7fb23c) at gstavviddec.c:1255
#54 0x00007fff4a39bd98 in gst_ffmpegviddec_frame (ffmpegdec=ffmpegdec@entry=0x7fff38039b80, data=data@entry=0x7fff3804b460 "", size=size@entry=743, got_data=got_data@entry=0x7fff3e7fb238, frame=frame@entry=0x7fff64063060, ret=ret@entry=0x7fff3e7fb23c) at gstavviddec.c:1312
#55 0x00007fff4a39c424 in gst_ffmpegviddec_handle_frame (decoder=0x7fff38039b80, frame=0x7fff64063060) at gstavviddec.c:1428
#56 0x00007fffebf299b9 in gst_video_decoder_decode_frame (decoder=decoder@entry=0x7fff38039b80, frame=0x7fff64063060) at gstvideodecoder.c:2760
#57 0x00007fffebf2c2f3 in gst_video_decoder_chain_forward (decoder=decoder@entry=0x7fff38039b80, buf=buf@entry=0x7fff60082620, at_eos=at_eos@entry=0) at gstvideodecoder.c:1757
#58 0x00007fffebf2da33 in gst_video_decoder_chain (pad=<optimized out>, parent=<optimized out>, buf=0x7fff60082620) at gstvideodecoder.c:2004
#59 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff60082620, type=4112, pad=0x7fff407f7ad0) at gstpad.c:3717
#60 gst_pad_push_data (pad=0x7fff30044fa0, type=type@entry=4112, data=<optimized out>) at gstpad.c:3950
#61 0x00007fffecc9d766 in gst_pad_push (pad=<optimized out>, buffer=<optimized out>) at gstpad.c:4053
#62 0x00007fffeca10d6b in gst_base_transform_chain (pad=<optimized out>, parent=<optimized out>, buffer=<optimized out>) at gstbasetransform.c:2237
#63 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff60082620, type=4112, pad=0x7fff3003dc90) at gstpad.c:3717
#64 gst_pad_push_data (pad=0x7fff0c888900, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff60082620) at gstpad.c:3950
#65 0x00007fffecc9d766 in gst_pad_push (pad=<optimized out>, buffer=buffer@entry=0x7fff60082620) at gstpad.c:4053
#66 0x00007fffec9f2a4f in gst_base_parse_push_frame (parse=parse@entry=0x7fff3401d230, frame=frame@entry=0x7fff3e7fb880) at gstbaseparse.c:2280
#67 0x00007fffec9f36c8 in gst_base_parse_chain (pad=<optimized out>, parent=<optimized out>, buffer=0x7fff60082620) at gstbaseparse.c:2758
#68 0x00007fffecc96915 in gst_pad_chain_data_unchecked (data=0x7fff60082620, type=4112, pad=0x7fff1800b6b0) at gstpad.c:3717
#69 gst_pad_push_data (pad=0x7fff0803cdf0, type=type@entry=4112, data=<optimized out>, data@entry=0x7fff60082620) at gstpad.c:3950
#70 0x00007fffecc9d766 in gst_pad_push (pad=<optimized out>, buffer=buffer@entry=0x7fff60082620) at gstpad.c:4053
#71 0x00007fff7c381181 in gst_single_queue_push_one (object=0x7fff60082620, sq=0x7fff34055480, mq=0x8501b0) at gstmultiqueue.c:1083
#72 gst_multi_queue_loop (pad=<optimized out>) at gstmultiqueue.c:1331
#73 0x00007fffeccc4929 in gst_task_func (task=0x7fff6000f4d0) at gsttask.c:316
#74 0x00007fffef6aaab6 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#75 0x00007fffef6aa0f5 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#76 0x00007fffeebdef6e in start_thread (arg=0x7fff3e7fc700) at pthread_create.c:311
#77 0x00007fffee9099cd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

[Brendan Long]

Actually I think that backtrace is unrelated (or related but unhelpful). I used G_DEBUG=fatal_criticals to break on that first error log, and it looks like the problem is that TextCombinerGStreamer's "tags" property is used in several threads with no locking.

[Brendan Long]

I added some locking, copy the GstTagList before returning it, and added a bunch of ASSERTs, and still get the same messages. Even with something like this:

        static void webkitTextCombinerPadGetProperty(GObject* object, guint propertyId, GValue* value, GParamSpec* pspec)
        {
            WebKitTextCombinerPad* pad = WEBKIT_TEXT_COMBINER_PAD(object);
            switch (propertyId) {
            case PROP_PAD_TAGS: {
                GST_OBJECT_LOCK(object);
                ASSERT(GST_IS_TAG_LIST(pad->tags));
                ASSERT(GST_OBJECT_REFCOUNT(pad->tags) > 0);
                GstTagList* tags = gst_tag_list_copy(pad->tags);
                ASSERT(GST_IS_TAG_LIST(tags));
                ASSERT(GST_OBJECT_REFCOUNT(tags) > 0);
                g_value_set_boxed(value, tags);
                GST_OBJECT_UNLOCK(object);
                break;
            }
            default:
                G_OBJECT_WARN_INVALID_PROPERTY_ID(object, propertyId, pspec);
                break;
            }
        }

I'll get an error message in g_object_unset in g_object_get_valist:

    (DumpRenderTree:541): GStreamer-CRITICAL **: __gst_tag_list_free: assertion 'GST_IS_TAG_LIST (list)' failed

How can that possibly not be a GstTagList?

The relevant snippet in g_object_get_valist is:

      object_get_property (object, pspec, &value);
      
      G_VALUE_LCOPY (&value, var_args, 0, &error);
      if (error)
	{
	  g_warning ("%s: %s", G_STRFUNC, error);
	  g_free (error);
	  g_value_unset (&value);
	  break;
	}
      
      g_value_unset (&value);

And object_get_property just runs some checks and then runs:

    class->get_property (object, param_id, value, pspec);

So, somehow things are going run somewhere around here.

Since nothing makes sense, maybe it's stack smashing, but I don't see anywhere where the stack could get smashed :\

[Brendan Long]

Oh, and m_pad has 7 refs and `tags` in notifyTrackOfTagsChanged() is a GstTagList, but has no refs:

print *tags.get()
$3 = {mini_object = {type = 140734468604784, refcount = 0, lockstate = 0, flags = 0, 
    copy = 0x7fffecdd3d50 <__gst_tag_list_copy>, dispose = 0x0, 
    free = 0x7fffecdd3cf0 <__gst_tag_list_free>, n_qdata = 0, qdata = 0x0}}

[Brendan Long]

One issue is that GValue is calling __gst_tag_list_free instead of gst_tag_list_unref, but it should still work since it uses __gst_tag_list_copy to copy it.

static void
__gst_tag_list_free (GstTagList * list)
{
  g_return_if_fail (GST_IS_TAG_LIST (list));

#ifdef DEBUG_REFCOUNT
  GST_CAT_TRACE (GST_CAT_TAGS, "freeing taglist %p", list);
#endif

  gst_structure_free (GST_TAG_LIST_STRUCTURE (list));

  g_slice_free1 (sizeof (GstTagListImpl), list);
}

static GstTagList *
__gst_tag_list_copy (const GstTagList * list)
{
  const GstStructure *s;

  g_return_val_if_fail (GST_IS_TAG_LIST (list), NULL);

  s = GST_TAG_LIST_STRUCTURE (list);
  return gst_tag_list_new_internal (gst_structure_copy (s));
}

[Brendan Long]

I've been looking in the wrong place. The crash is in AudioTrackPrivateGStreamer, so the relevant code is in input-selector, not WebKitTextCombiner.

[Brendan Long]

Created attachment 218876 [details]
Patch

[Philippe Normand]

Comment on attachment 218876 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=218876&action=review

> Source/WebCore/ChangeLog:8
> +        No new tests because this fixes flakeyness in existing tests (media/video-preload.h, and various tests in media/track/{audio,in-band,video}).

.html

> Source/WebCore/platform/graphics/gstreamer/TextCombinerGStreamer.cpp:209
> +        GstTagList* oldTags = combinerPad->tags;
> +        combinerPad->tags = gst_tag_list_merge(combinerPad->tags, tags, GST_TAG_MERGE_REPLACE);
> +        if (oldTags)
> +            gst_tag_list_unref(oldTags);

Not sure to understand this, seems a bit confusing to me :/

> Source/WebCore/platform/graphics/gstreamer/TrackPrivateBaseGStreamer.cpp:78
> +    /* We can't call notifyTrackOfTagsChanged() directly, because we need tagsChanged()

Nit: please use // comments :)

[Brendan Long]

Created attachment 218879 [details]
Patch

[Philippe Normand]

Comment on attachment 218879 [details]
Patch

Ok!

[Brendan Long]

I think I'll work on something that doesn't involve multiple threads next..

[WebKit Commit Bot]

Comment on attachment 218879 [details]
Patch

Clearing flags on attachment: 218879

Committed r160375: <http://trac.webkit.org/changeset/160375>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.