Bug 196691 – [GStreamer] gst_element_get_state: assertion 'GST_IS_ELEMENT (element)' failed in WebCore::MediaPlayerPrivateGStreamer::paused

• Component: Media
• Status: RESOLVED FIXED

[Michael Catanzaro]

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.

[Philippe Normand]

This backtrace doesn't look very useful. What's in m_pipeline?

[Michael Catanzaro]

I don't know why it's not included in the backtrace. It must be either nullptr or  else dangling.

[Philippe Normand]

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

[Michael Catanzaro]

Indeed the error is gone today, oh well :/

[Philippe Normand]

Let's close this then. Reopen (with logs) if/when the issue happens again :)

[Michael Catanzaro]

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).

[Michael Catanzaro]

Created attachment 367858 [details]
Debug log

[Michael Catanzaro]

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....

[Philippe Normand]

I can reproduce it. Will have a look!

[Philippe Normand]

(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.

[Philippe Normand]

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

[Eric Carlson]

> 
> 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.

[Philippe Normand]

Ah right, forcing the 2 state changes is the way to go. I was not notifying the player correctly. Thanks!

[Philippe Normand]

Created attachment 368141 [details]
Patch

[Philippe Normand]

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.

[Philippe Normand]

Committed r244641: <https://trac.webkit.org/changeset/244641>

[Radar WebKit Bug Importer]

<rdar://problem/50197848>