Bug 196691

Summary: [GStreamer] gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed in WebCore::MediaPlayerPrivateGStreamer::paused
Product: WebKit Reporter: Michael Catanzaro <mcatanzaro>
Component: MediaAssignee: Philippe Normand <pnormand>
Status: RESOLVED FIXED    
Severity: Normal CC: bugs-noreply, eric.carlson, mcatanzaro, pnormand, webkit-bug-importer
Priority: P2 Keywords: InRadar
Version: WebKit Nightly Build   
Hardware: PC   
OS: Linux   
Attachments:
Description Flags
Debug log
none
Patch eric.carlson: review+

Description Michael Catanzaro 2019-04-08 07:45:56 PDT
Loading https://reddit.com in trunk:

(WebKitWebProcess:50441): GStreamer-CRITICAL **: 09:39:25.042: gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed

(WebKitWebProcess:50441): GStreamer-CRITICAL **: 09:39:25.042: gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed

(WebKitWebProcess:50441): GStreamer-CRITICAL **: 09:39:25.042: gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed

(WebKitWebProcess:50441): GStreamer-CRITICAL **: 09:39:25.042: gst_element_set_state: assertion 'GST_IS_ELEMENT (element)' failed

(WebKitWebProcess:50441): GStreamer-CRITICAL **: 09:39:26.373: gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed

It's coming from WebCore::MediaPlayerPrivateGStreamer::paused:

(gdb) bt full
#0  _g_log_abort (breakpoint=1)
    at ../../../../Projects/glib/glib/gmessages.c:557
        debugger_present = 1
#1  0x00007fe4487e818c in g_logv (log_domain=0x7fe448fb2960 "GStreamer", 
    log_level=G_LOG_LEVEL_CRITICAL, 
    format=0x7fe44884788d "%s: assertion '%s' failed", args=0x7ffcc8a09b88)
    at ../../../../Projects/glib/glib/gmessages.c:1371
        domain = 0x0
        data = 0x0
        depth = 1
        log_func = 0x7fe448f035b0
        domain_fatal_mask = 5
        masquerade_fatal = 0
        test_level = 10
        was_fatal = 0
        was_recursion = 0
        buffer = "`\254\376\250)\000\000\034\200\363]\261\317\177\000\000\370\377\377\377\000\000\000\000\203\300\254K\344\177\000\000\000\000\000\000\000\000\000\000\353ҷK\344\177\000\000\200\363]\261\317\177\000\000\370\377\377\377\000\000\000\000\200\363]\261\317\177\000\000\032\230\270K\344\177\000\000T\254\376\250\317\177\000\000\001\000\000\000\317\177\000\000\230⚨\000\000\000\000\200\227\240\310\374\177\000\000\370\377\377\377\370\377\377\377\300\370R\250\317\177\000\000\200\227\240\310\374\177\000\000\005\000\000\000\005", '\000' <repeats 43 t--Type <RET> for more, q to quit, c to continue without paging--
imes>, "\346\066\264K\344\177\000\000\004\364]\261\317\177\000\000T\254\376"...
        msg = 0x2d8aa80 "gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed"
        msg_alloc = 0x2d8aa80 "gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed"
        i = 3
#2  0x00007fe4487e827d in g_log (log_domain=0x7fe448fb2960 "GStreamer", 
    log_level=G_LOG_LEVEL_CRITICAL, 
    format=0x7fe44884788d "%s: assertion '%s' failed")
    at ../../../../Projects/glib/glib/gmessages.c:1413
        args = {{gp_offset = 40, fp_offset = 48, 
            overflow_arg_area = 0x7ffcc8a09c60, 
            reg_save_area = 0x7ffcc8a09ba0}}
#3  0x00007fe4487ea12c in g_return_if_fail_warning (
    log_domain=0x7fe448fb2960 "GStreamer", 
    pretty_function=0x7fe448fbd8e0 "gst_element_get_state", 
    expression=0x7fe448fb3c32 "GST_IS_ELEMENT (element)")
    at ../../../../Projects/glib/glib/gmessages.c:2767
No locals.
#4  0x00007fe448f34aa2 in gst_element_get_state ()
   from /lib64/libgstreamer-1.0.so.0
No symbol table info available.
#5  0x00007fe44ed54d5a in WebCore::MediaPlayerPrivateGStreamer::paused (
--Type <RET> for more, q to quit, c to continue without paging--
    this=0x7fe436b7c700)
    at /home/mcatanzaro/Projects/WebKit/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp:658
        state = 32719
        paused = <optimized out>
        __FUNCTION__ = <optimized out>
        state = <optimized out>
        paused = <optimized out>
        _g_boolean_var_ = <optimized out>
        _g_boolean_var_ = <optimized out>
        _g_boolean_var_ = <optimized out>
#6  WebCore::MediaPlayerPrivateGStreamer::paused (this=0x7fe436b7c700)
    at /home/mcatanzaro/Projects/WebKit/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp:645
        state = <optimized out>
        paused = <optimized out>
        __FUNCTION__ = <optimized out>
        _g_boolean_var_ = <optimized out>
        _g_boolean_var_ = <optimized out>
#7  0x00007fe44e30f033 in WebCore::HTMLMediaElement::updatePlayState (
    this=0x7fe410c007b8)
    at DerivedSources/ForwardingHeaders/wtf/DumbPtrTraits.h:41
        shouldBePlaying = false
--Type <RET> for more, q to quit, c to continue without paging--
        playerPaused = <optimized out>
        shouldBePlaying = <optimized out>
        playerPaused = <optimized out>
        page = <optimized out>
        time = <optimized out>
#8  WebCore::HTMLMediaElement::updatePlayState (this=0x7fe410c007b8)
    at /home/mcatanzaro/Projects/WebKit/Source/WebCore/html/HTMLMediaElement.cpp:5429
        shouldBePlaying = <optimized out>
        playerPaused = <optimized out>
        page = <optimized out>
        time = <optimized out>
#9  0x00007fe44e30f8a1 in WebCore::HTMLMediaElement::pauseInternal (
    this=0x7fe410c007b8)
    at /home/mcatanzaro/Projects/WebKit/Source/WebCore/html/HTMLMediaElement.cpp:3685
No locals.
#10 WebCore::HTMLMediaElement::pauseInternal (this=0x7fe410c007b8)
    at /home/mcatanzaro/Projects/WebKit/Source/WebCore/html/HTMLMediaElement.cpp:3641
No locals.
#11 0x00007fe44e30fa0c in WebCore::HTMLMediaElement::pause (
    this=0x7fe410c007b8)
--Type <RET> for more, q to quit, c to continue without paging--
    at /home/mcatanzaro/Projects/WebKit/Source/WebCore/html/HTMLMediaElement.cpp:3637
No locals.
#12 WebCore::HTMLMediaElement::pause (this=0x7fe410c007b8)
    at /home/mcatanzaro/Projects/WebKit/Source/WebCore/html/HTMLMediaElement.cpp:3622
No locals.
#13 0x00007fe44d93aabd in WebCore::jsHTMLMediaElementPrototypeFunctionPauseBody
    (state=<optimized out>, throwScope=..., castedThis=<optimized out>)
    at DerivedSources/WebCore/JSHTMLMediaElement.cpp:1556
        impl = <optimized out>
        impl = <optimized out>
#14 WebCore::IDLOperation<WebCore::JSHTMLMediaElement>::call<WebCore::jsHTMLMediaElementPrototypeFunctionPauseBody> (operationName=0x7fe44efbb4eb "pause", 
    state=...)
    at /home/mcatanzaro/Projects/WebKit/Source/WebCore/bindings/js/JSDOMOperation.h:53
        throwScope = {<JSC::ExceptionScope> = {m_vm = 
    @0x7fe41c200000}, <No data fields>}
        thisObject = <optimized out>
        throwScope = <optimized out>
        thisObject = <optimized out>
#15 WebCore::jsHTMLMediaElementPrototypeFunctionPause (state=<optimized out>)
--Type <RET> for more, q to quit, c to continue without paging--
    at DerivedSources/WebCore/JSHTMLMediaElement.cpp:1562
No locals.
#16 0x00007fcfbffff16b in ?? ()
No symbol table info available.
#17 0x00007ffcc8a09ee0 in ?? ()
No symbol table info available.
#18 0x00007fe44c149673 in llint_op_call ()
    at /home/mcatanzaro/Projects/WebKit/Source/JavaScriptCore/runtime/VMTraps.cpp:371
No symbol table info available.
#19 0x0000000000000000 in ?? ()
No symbol table info available.
Comment 1 Philippe Normand 2019-04-08 09:08:10 PDT
This backtrace doesn't look very useful. What's in m_pipeline?
Comment 2 Michael Catanzaro 2019-04-08 10:50:12 PDT
I don't know why it's not included in the backtrace. It must be either nullptr or  else dangling.
Comment 3 Philippe Normand 2019-04-09 06:18:46 PDT
I can't reproduce this issue. "Loading reddit" is quite a vague description, especially because it's quite fast-changing website.

Next time you see this error, please provide logs, GST_DEBUG=3,webkit*:6
Comment 4 Michael Catanzaro 2019-04-09 08:19:54 PDT
Indeed the error is gone today, oh well :/
Comment 5 Philippe Normand 2019-04-10 02:29:57 PDT
Let's close this then. Reopen (with logs) if/when the issue happens again :)
Comment 6 Michael Catanzaro 2019-04-19 18:10:05 PDT
Got it again today. The log ends with:

0:01:09.998282618 98709      0x14b1ea0 WARN       webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2204:loadingFailed: Loading failed, error: 4

(WebKitWebProcess:98709): GStreamer-CRITICAL **: 20:07:52.445: gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed

Will attach the whole thing. Reproducer is to just scroll down on the front page (G_DEBUG=fatal-criticals will help).
Comment 7 Michael Catanzaro 2019-04-19 18:10:20 PDT
Created attachment 367858 [details]
Debug log
Comment 8 Michael Catanzaro 2019-04-19 18:17:52 PDT
More from the ending:

0:01:09.998240909 98709      0x14b1ea0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2243:supportsType: Checking mime-type "image/gif"
0:01:09.998264264 98709      0x14b1ea0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2253:supportsType: Supported: IsNotSupported
0:01:09.998276707 98709      0x14b1ea0 DEBUG      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2287:setPreload: Setting preload to Auto
0:01:09.998282618 98709      0x14b1ea0 WARN       webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2204:loadingFailed: Loading failed, error: 4

(WebKitWebProcess:98709): GStreamer-CRITICAL **: 20:07:52.445: gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed

"image/gif" looks suspicious....
Comment 9 Philippe Normand 2019-04-24 05:24:16 PDT
I can reproduce it. Will have a look!
Comment 10 Philippe Normand 2019-04-24 09:06:10 PDT
(In reply to Michael Catanzaro from comment #8)
> More from the ending:
> 
> 0:01:09.998240909 98709      0x14b1ea0 DEBUG      webkitmediaplayer
> MediaPlayerPrivateGStreamer.cpp:2243:supportsType: Checking mime-type
> "image/gif"
> 0:01:09.998264264 98709      0x14b1ea0 DEBUG      webkitmediaplayer
> MediaPlayerPrivateGStreamer.cpp:2253:supportsType: Supported: IsNotSupported
> 0:01:09.998276707 98709      0x14b1ea0 DEBUG      webkitmediaplayer
> MediaPlayerPrivateGStreamer.cpp:2287:setPreload: Setting preload to Auto
> 0:01:09.998282618 98709      0x14b1ea0 WARN       webkitmediaplayer
> MediaPlayerPrivateGStreamer.cpp:2204:loadingFailed: Loading failed, error: 4
> 
> (WebKitWebProcess:98709): GStreamer-CRITICAL **: 20:07:52.445:
> gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed
> 
> "image/gif" looks suspicious....

Yeah that's indeed the issue. Our supportsType() returns IsNotSupported for image/gif but the MediaPlayer creates a GStreamer MediaPlayerPrivate anyway and tries to load that asset.

Eric, this looks like a bug in MediaPlayer::loadWithNextMediaEngine():


    // If no MIME type is specified or the type was inferred from the file extension, just use the next engine.
    if (!engine && (m_contentType.isEmpty() || m_contentMIMETypeWasInferredFromExtension))
        engine = nextMediaEngine(current);

m_contentType is not empty but m_contentMIMETypeWasInferredFromExtension is true, so the next engine is loaded, regardless of the supportsType() result.
Comment 11 Philippe Normand 2019-04-24 09:09:47 PDT
If this code has to remain, I think it would be good that MediaPlayerPrivate::load() methods return a bool result. WDYT?
Comment 12 Eric Carlson 2019-04-24 10:01:32 PDT
> 
> Yeah that's indeed the issue. Our supportsType() returns IsNotSupported for
> image/gif but the MediaPlayer creates a GStreamer MediaPlayerPrivate anyway
> and tries to load that asset.
> 
> Eric, this looks like a bug in MediaPlayer::loadWithNextMediaEngine():
> 
> 
>     // If no MIME type is specified or the type was inferred from the file
> extension, just use the next engine.
>     if (!engine && (m_contentType.isEmpty() ||
> m_contentMIMETypeWasInferredFromExtension))
>         engine = nextMediaEngine(current);
> 
> m_contentType is not empty but m_contentMIMETypeWasInferredFromExtension is
> true, so the next engine is loaded, regardless of the supportsType() result.

It does this on the assumption that because media file extensions are such a mess (e.g. look at the number of synonyms for "video/mpeg" in MIMETypeRegistry.cpp), it is  better to let the media engine look at the file in the absence of a MIME type. 


> If this code has to remain, I think it would be good that MediaPlayerPrivate::load() methods return a bool result. WDYT?

That would require MediaPlayerPrivate::load to be synchronous, which is usually impossible. 

If the MediaPlayerPrivate calls MediaPlayer::networkStateChanged() with networkState >= FormatError and readyState < HaveMetadata, MediaPlayer will try with with the next media engine or pass the error to HTMLMediaElement if there are none.
Comment 13 Philippe Normand 2019-04-24 10:40:21 PDT
Ah right, forcing the 2 state changes is the way to go. I was not notifying the player correctly. Thanks!
Comment 14 Philippe Normand 2019-04-24 10:44:37 PDT
Created attachment 368141 [details]
Patch
Comment 15 Philippe Normand 2019-04-24 11:38:08 PDT
Comment on attachment 368141 [details]
Patch

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

> LayoutTests/platform/gtk/TestExpectations:-1649
> -# Crash is webkit.org/b/176802
> -webkit.org/b/36642 fast/replaced/border-radius-clip.html [ Failure Pass Crash ]

It might still be flaky, I'll remove the Crash mentions only, for now.
Comment 16 Philippe Normand 2019-04-25 00:52:52 PDT
Committed r244641: <https://trac.webkit.org/changeset/244641>
Comment 17 Radar WebKit Bug Importer 2019-04-25 00:53:16 PDT
<rdar://problem/50197848>