Bug 177409 – [GStreamer][MSE] gstreamer critical warning in gst_buffer_pool_acquire_buffer()

• Status: NEW
• Component: WebKitGTK

[Alicia Boya García]

How to reproduce:

1. Merge the webm patch https://bugs.webkit.org/show_bug.cgi?id=177355
2. Load the following page: http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/2018.html?tests=56&command=run

After the test completes (passing), a GStreamer warning is printed.

http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  Media Source and Encrypted Media Conformance Tests (version 20170922171024-vKiynwyVqklah7cE) 
http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  Test 56:AppendVP9Video STARTED with timeout 30000 
http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  checkEq passed: Source buffer number is (1). 
http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  checkEq passed: Range start is (0). 
http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  checkApproxEq passed: Range end is (0.999777). 
http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  Test 56:AppendVP9Video PASSED. 
http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  New longest test AppendVP9Video with timeout 30000 takes 1239 

(WebKitWebProcess:23826): GStreamer-CRITICAL **: gst_buffer_pool_acquire_buffer: assertion 'GST_IS_BUFFER_POOL (pool)' failed
http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  Longest test is AppendVP9Video, it takes 0.0413 of its timeout. 
http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/js/harness/main-20170922171024.js:123:16: CONSOLE LOG TestExecutor:  All tests are completed 

This is the backtrace, captured by setting a breakpoint in `g_log()`:

#0  g_log () at /webkit/WebKitBuild/DependenciesGTK/Source/glib-2.52.1/glib/gmessages.c:1394
#1  0x00007fffe27e3c5f in gst_buffer_pool_acquire_buffer () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstbufferpool.c:1251
#2  0x00007fffe1e9649b in gst_video_decoder_allocate_output_frame () at /webkit/WebKitBuild/DependenciesGTK/Source/gst-plugins-base-1.10.5/gst-libs/gst/video/gstvideodecoder.c:3987
#3  0x00007fff4ccf262f in gst_vpx_dec_handle_frame () at /webkit/WebKitBuild/DependenciesGTK/Source/gst-plugins-good-1.10.5/ext/vpx/gstvpxdec.c:712
#4  0x00007fffe1e8be6e in gst_video_decoder_decode_frame () at /webkit/WebKitBuild/DependenciesGTK/Source/gst-plugins-base-1.10.5/gst-libs/gst/video/gstvideodecoder.c:3389
#5  0x00007fffe1e8e7d8 in gst_video_decoder_chain_forward () at /webkit/WebKitBuild/DependenciesGTK/Source/gst-plugins-base-1.10.5/gst-libs/gst/video/gstvideodecoder.c:2131
#6  0x00007fffe1e8ee53 in gst_video_decoder_chain () at /webkit/WebKitBuild/DependenciesGTK/Source/gst-plugins-base-1.10.5/gst-libs/gst/video/gstvideodecoder.c:2443
#7  0x00007fffe2814567 in gst_pad_chain_data_unchecked () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4202
#8  gst_pad_push_data () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4454
#9  0x00007fffe281c483 in gst_pad_push () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4573
#10 0x00007fffe2814567 in gst_pad_chain_data_unchecked () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4202
#11 gst_pad_push_data () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4454
#12 0x00007fffe281c483 in gst_pad_push () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4573
#13 0x00007fffe28043eb in gst_proxy_pad_chain_default () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstghostpad.c:126
#14 0x00007fffe2814567 in gst_pad_chain_data_unchecked () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4202
#15 gst_pad_push_data () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4454
#16 0x00007fffe281c483 in gst_pad_push () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4573
#17 0x00007fffe28043eb in gst_proxy_pad_chain_default () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstghostpad.c:126
#18 0x00007fffe2814567 in gst_pad_chain_data_unchecked () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4202
#19 gst_pad_push_data () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4454
#20 0x00007fffe281c483 in gst_pad_push () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gstpad.c:4573
#21 0x00007fffe2b04775 in gst_base_src_loop () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/libs/gst/base/gstbasesrc.c:2854
#22 0x00007fffe2847249 in gst_task_func () at /webkit/WebKitBuild/DependenciesGTK/Source/gstreamer-1.10.5/gst/gsttask.c:334
#23 0x00007fffe03fe100 in g_thread_pool_thread_proxy () at /webkit/WebKitBuild/DependenciesGTK/Source/glib-2.52.1/glib/gthreadpool.c:307
#24 0x00007fffe03fd775 in g_thread_proxy () at /webkit/WebKitBuild/DependenciesGTK/Source/glib-2.52.1/glib/gthread.c:784
#25 0x00007fffdca2836d in start_thread (arg=0x7fff4d6ff700) at pthread_create.c:456
#26 0x00007fffdb670bbf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

`pool` variable is null, but it's not clear where it got that value from.

[Alicia Boya García]

I got this crash again and looked at it. At first it seemed very strange: why would the VP9 decoder have not initialized a buffer pool?

After looking at the gst log though, it all came clear: this critical happend just after destroying MediaPlayerPrivateGStreamerMSE.

At that point no streaming threads should be running. There is a race condition somewhere in the deinitialization code of the MSE player.

MediaSource::setReadyState(0x7fff5b8f8d20) : open -> closed
MediaSource::removeSourceBuffer() 0x7fff5b8f8d20
0:03:17.235106404 10336       0x4b4b00 DEBUG              webkitmse MediaSourceClientGStreamerMSE.cpp:99:abort: MediaSourceClientGStreamerMSE::abort
0:03:17.235231234 10336       0x4b4b00 DEBUG              webkitmse AppendPipeline.cpp:215:deinitialize:0x7fff7c0881e0 Deinitializating AppendPipeline (0x7fff7c0881e0)
0:03:17.235243074 10336       0x4b4b00 TRACE              webkitmse AppendPipeline.cpp:221:deinitialize:0x7fff7c0881e0 Setting AppendPipeline to GST_STATE_NULL (0x7fff7c0881e0)
0:03:17.235266926 10336       0x4b4b00 DEBUG               basesink gstbasesink.c:5153:gst_base_sink_change_state:<appsink84> PLAYING to PAUSED
0:03:17.235272506 10336       0x4b4b00 DEBUG               basesink gstbasesink.c:5162:gst_base_sink_change_state:<appsink84> got preroll lock
0:03:17.235275895 10336       0x4b4b00 DEBUG               basesink gstbasesink.c:3341:gst_base_sink_needs_preroll:<appsink84> have_preroll: 0, EOS: 0 => needs preroll: 1
0:03:17.235281909 10336       0x4b4b00 DEBUG               basesink gstbasesink.c:5184:gst_base_sink_change_state:<appsink84> PLAYING to PAUSED, we are not prerolled
0:03:17.235285351 10336       0x4b4b00 DEBUG               basesink gstbasesink.c:5198:gst_base_sink_change_state:<appsink84> rendered: 36, dropped: 0
0:03:17.235327006 10336       0x4b4b00 DEBUG               basesink gstbasesink.c:4159:gst_base_sink_set_flushing:<appsink84> flushing out data thread, need preroll to TRUE
0:03:17.235345164 10336       0x4b4b00 TRACE              webkitmse AppendPipeline.cpp:1046:appsinkCapsChanged:0x7fff7c0881e0 appsink-caps-changed message posted to bus
0:03:17.235353821 10336       0x4b4b00 DEBUG               basesink gstbasesink.c:994:gst_base_sink_set_last_buffer_unlocked:<appsink84> setting last buffer to (nil)
0:03:17.235755204 10336       0x4b4b00 DEBUG              webkitmse AppendPipeline.cpp:987:disconnectDemuxerSrcPadFromAppsinkFromAnyThread:0x7fff7c0881e0 Disconnecting appsink
0:03:17.236144897 10336       0x4b4b00 DEBUG              webkitmse PlaybackPipeline.cpp:153:removeSourceBuffer:<source> Element removed from MediaSource
0:03:17.236260974 10336       0x4b4b00 DEBUG              webkitmse AppendPipeline.cpp:215:deinitialize:0x7fff7c0881e0 Deinitializating AppendPipeline (0x7fff7c0881e0)
0:03:17.236269171 10336       0x4b4b00 TRACE              webkitmse AppendPipeline.cpp:208:~AppendPipeline:0x7fff7c0881e0 Destroying AppendPipeline (0x7fff7c0881e0)
MediaSource::removeSourceBuffer() 0x7fff5b8f8d20
0:03:17.236334569 10336       0x4b4b00 DEBUG              webkitmse AppendPipeline.cpp:215:deinitialize:0x7fff7c0882d0 Deinitializating AppendPipeline (0x7fff7c0882d0)
0:03:17.236341392 10336       0x4b4b00 TRACE              webkitmse AppendPipeline.cpp:221:deinitialize:0x7fff7c0882d0 Setting AppendPipeline to GST_STATE_NULL (0x7fff7c0882d0)
0:03:17.236474009 10336       0x4b4b00 DEBUG              webkitmse PlaybackPipeline.cpp:153:removeSourceBuffer:<source> Element removed from MediaSource
0:03:17.236485041 10336       0x4b4b00 DEBUG              webkitmse AppendPipeline.cpp:215:deinitialize:0x7fff7c0882d0 Deinitializating AppendPipeline (0x7fff7c0882d0)
0:03:17.236490246 10336       0x4b4b00 TRACE              webkitmse AppendPipeline.cpp:208:~AppendPipeline:0x7fff7c0882d0 Destroying AppendPipeline (0x7fff7c0882d0)
0:03:17.236533703 10336       0x4b4b00 TRACE              webkitmse MediaPlayerPrivateGStreamerMSE.cpp:119:~MediaPlayerPrivateGStreamerMSE: destroying the player (0x7fff8c58f040)
0:03:17.236545856 10336       0x4b4b00 DEBUG              webkitmse PlaybackPipeline.cpp:97:setWebKitMediaSrc: webKitMediaSrc=(nil)

(WebKitWebProcess:10336): GStreamer-CRITICAL **: gst_buffer_pool_acquire_buffer: assertion 'GST_IS_BUFFER_POOL (pool)' failed

[Alicia Boya García]

Despite the initial logs, this bug is more easily reproduced by just running  58. TimestampOffsetVP9Video. The assertion error happens just after the test finishes. Reproducible 100% of the time.

[Michael Catanzaro]

imported/w3c/web-platform-tests/media-source/mediasource-changetype.html is regularly crashing on this. I'm adding an expectation; please remove it when fixed.

[Philippe Normand]

> 2. Load the following page: http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/2018.html?tests=56&command=run

That's a dead end, I see some XML error message:

<Error>
<Code>NoSuchKey</Code>
<Message>The specified key does not exist.</Message>
<Details>
No such object: yt-dash-mse-test/unit-tests/2018.html
</Details>
</Error>

[Enrique Ocaña]

The YouTube MSE tests 2018 aren't online anymore. You "might" have some chance of reproducing a similar problem (I haven't tried it myself) on the equivalend test ("62. TimestampOffsetVP9Video") on YT MSE 2019 tests, which are still online: https://ytlr-cert.appspot.com/2019/main.html

[Philippe Normand]

(In reply to Alicia Boya García from comment #2)
> Despite the initial logs, this bug is more easily reproduced by just running
> 58. TimestampOffsetVP9Video. The assertion error happens just after the test
> finishes. Reproducible 100% of the time.

Test "62. TimestampOffsetVP9Video" of the YT MSE 2019 tests is passing here.

(In reply to Michael Catanzaro from comment #3)
> imported/w3c/web-platform-tests/media-source/mediasource-changetype.html is
> regularly crashing on this. I'm adding an expectation; please remove it when
> fixed.

This is now flagged as a failure/crash, see https://bugs.webkit.org/show_bug.cgi?id=167108

[Michael Catanzaro]

We received a complaint about this here: https://discourse.gnome.org/t/gnome-web-epiphany-crashes/23455

[Philippe Normand]

(In reply to Michael Catanzaro from comment #7)
> We received a complaint about this here:
> https://discourse.gnome.org/t/gnome-web-epiphany-crashes/23455

That remains to be confirmed.

[John Scott]

(In reply to Philippe Normand from comment #8)
> (In reply to Michael Catanzaro from comment #7)
> > We received a complaint about this here:
> > https://discourse.gnome.org/t/gnome-web-epiphany-crashes/23455
> 
> That remains to be confirmed.

Hello! I'm a Debian Maintainer using unstable ("sid") who is able to reproduce this. In fact, I found that user's complaint on GNOME Discourse after searching around with my logs. The situation is basically identical: I get the same warnings from Mesa/Vulkan with Intel HD Graphics and reproduce this most often with Facebook, but sometimes with other sites using JavaScript and media extensively.

I don't maintain Epiphany (or any relevant packages for that matter) in Debian, but do help with GNOME issues sometimes. If I'm able to get a nice stack trace or other juicy details I'll send those here.