Bug 177409 - [GStreamer][MSE] gstreamer critical warning in gst_buffer_pool_acquire_buffer()
Summary: [GStreamer][MSE] gstreamer critical warning in gst_buffer_pool_acquire_buffer()
Status: NEW
Alias: None
Product: WebKit
Classification: Unclassified
Component: WebKitGTK (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Nobody
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-09-23 11:29 PDT by Alicia Boya García
Modified: 2023-01-05 10:42 PST (History)
4 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Alicia Boya García 2017-09-23 11:29:43 PDT
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.
Comment 1 Alicia Boya García 2018-01-19 14:21:59 PST
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
Comment 2 Alicia Boya García 2018-11-28 06:11:55 PST
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.
Comment 3 Michael Catanzaro 2019-01-20 12:02:06 PST
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.
Comment 4 Philippe Normand 2023-01-05 09:14:10 PST
> 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>
Comment 5 Enrique Ocaña 2023-01-05 10:09:37 PST
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
Comment 6 Philippe Normand 2023-01-05 10:42:02 PST
(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