Bug 227882 – [GStreamer][MSE] Critical warnings when flushing

• Component: Media
• Status: NEW

[Michael Catanzaro]

Created attachment 433344 [details]
Screencast

* Choose some video from https://vimeo.com/watch
 * Start playing the video in Ephy Tech Preview and note it is working fine
 * Seek the video. The first seek does not work and causes video playback to restart from the beginning. Loads of GStreamer warnings print on the terminal.
 * Seek the video again. The video playback gets all messed up.

Screencast and GStreamer log attached. The warnings from the initial seek look like this:

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.088: ../gst/gstpad.c:4549:gst_pad_push_data:<fdkaacdec0:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audio_0:proxypad18> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<decodebin3-0:audio_0> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audio_0:proxypad19> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<uridecodebin3-0:audio_0> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audio-concat:sink_0> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<audio-concat:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<playsink:audio_sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<audio_sink:proxypad7> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audiotee:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<audiotee:src_0> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<streamsynchronizer0:sink_1> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<streamsynchronizer0:src_1> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<abin:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<sink:proxypad27> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<filter-convert:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<filter-convert:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<scaletempo0:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<scaletempo0:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<aqueue:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<aqueue:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<aconv:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<sink:proxypad25> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<conv:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<conv:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<resample:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<resample:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<src:proxypad26> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<aconv:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audio-sink:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<sink:proxypad1> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audioTee:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<audioTee:src_0> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<queue0:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<queue0:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audioconvert0:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<audioconvert0:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audioresample0:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<audioresample0:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<volume:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-CRITICAL **: 14:51:26.089: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<volume:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audioconvert1:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<audioconvert1:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<audioresample1:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<audioresample1:src> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<autoaudiosink0:sink> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4549:gst_pad_push_data:<sink:proxypad0> Got data flow before segment event

(WebKitWebProcess:170): GStreamer-WARNING **: 14:51:26.089: ../gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<autoaudiosink0-actual-sink-pulse:sink> Got data flow before segment event

[Michael Catanzaro]

Created attachment 433345 [details]
GStreamer debug log

[Philippe Normand]

Works fine in ToT.

[Philippe Normand]

Maybe another symptom of a broken runtime ;)

0:00:12.769677211   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.769714743   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.769738808   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.769779385   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.769804864   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.769840241   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.769868665   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.769892410   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.769968976   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 5
0:00:12.770011286   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.770050791   170 0x7fe79000fea0 WARN            audiodecoder gstaudiodecoder.c:3181:_gst_audio_decoder_error:<fdkaacdec0> error: decoding error: 4098
0:00:12.770133909   170 0x7fe77800e4c0 WARN                basesink gstbasesink.c:3495:gst_base_sink_chain_unlocked:<autoaudiosink0-actual-sink-pulse> warning: Internal data flow problem.
0:00:12.770191508   170 0x7fe77800e4c0 WARN                basesink gstbasesink.c:3495:gst_base_sink_chain_unlocked:<autoaudiosink0-actual-sink-pulse> warning: Received buffer without a new-segment. Assuming timestamps start from 0.
0:00:12.770149148   170 0x5600ec3bf750 LOG        webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1775:handleMessage:<MSE-media-player-0> Message error received from element fdkaacdec0
0:00:12.770245521   170 0x5600ec823aa0 ERROR         webkitmediasrc WebKitMediaSourceGStreamer.cpp:518:webKitMediaSrcLoop:<source:src_A1> Pushing buffer returned error
0:00:12.770247825   170 0x5600ec3bf750 ERROR      webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:1781:handleMessage: Error 7: Could not decode stream. (url=mediasourceblob:https://vimeo.com/7614ff3b-8476-48d2-982c-a682b4d0b6b5)

[Sun]

I have a similar issue : vimeo video jerky but with a getUserMedia.

- On an iPhone with OS 14.5, go to https://codepen.io/sunlimet/pen/yLbgOEx
- Button share, then "Add to Home Screen"
- Open PWA, press play = video is lagging
- As you can see, there's only the Vimeo iframe and a navigator.mediaDevices.getUserMedia

Android do not have this issue, Chrome either.
Can reproduce on old IPhones (SE first and second generation, iPhone 6), but it's ok on iPhone 11

In Safari standalone (not PWA), it is better but it's also lagging

[Philippe Normand]

(In reply to Sun from comment #4)
> I have a similar issue : vimeo video jerky but with a getUserMedia.
> 
> - On an iPhone with OS 14.5, go to https://codepen.io/sunlimet/pen/yLbgOEx
> - Button share, then "Add to Home Screen"
> - Open PWA, press play = video is lagging
> - As you can see, there's only the Vimeo iframe and a
> navigator.mediaDevices.getUserMedia
> 
> Android do not have this issue, Chrome either.
> Can reproduce on old IPhones (SE first and second generation, iPhone 6), but
> it's ok on iPhone 11
> 
> In Safari standalone (not PWA), it is better but it's also lagging

This specific bug is about GStreamer ports. Apple ports don't use GStreamer, please file a new bug.

[Michael Catanzaro]

(In reply to Philippe Normand from comment #3)
> Maybe another symptom of a broken runtime ;)

FWIW I've been prodding about GStreamer updates, and we are now *tentatively* planning to start updating GStreamer in the GNOME runtime, but only once we switch to buildstream 2, which apparently makes it easier to override elements built by freedesktop-sdk. That way, freedesktop-sdk can stick with one branch of GStreamer for an entire year, but GNOME can update to a newer branch twice per year.

However, buildstream seems to have run out of development funding, so the timeline for this is uncertain. In the meantime, GStreamer devs are well aware of our release cycle....

[Michael Catanzaro]

Still broken with the 21.08 runtime (including GStreamer 1.18)

[Michael Catanzaro]

Also happens on cnn.com:

https://www.cnn.com/videos/politics/2021/08/11/cory-booker-tommy-tuberville-defund-the-police-newday-vpx.cnn/video/playlists/this-week-in-politics/

Sometimes it even starts flickering without requiring a seek, but if not, then a seek should be sufficient to reproduce.

I also recently noticed this happening inconsistently on youtube.com as well, although it's a lot harder to reproduce on youtube.com for some reason.

[Michael Catanzaro]

Much lighter example: https://dynaimage.cdn.cnn.com/cnn/animations/w_307/210813092733-desktop-race-dotmap.mp4

[Michael Catanzaro]

I'm hitting this 100% of the time when viewing https://www.nbcnews.com/news/us-news/hannah-kobayashi-says-was-unaware-frenzy-family-reported-missing-rcna184463?

Except nowadays, since criticals are now fatal in Epiphany, it's just an immediate crash instead of a video playback problem.

Updated backtrace:

(gdb) bt
#0  _g_log_abort (breakpoint=<optimized out>) at ../glib/gmessages.c:431
#1  g_logv (log_domain=0x7f09e05f99ae "GStreamer", log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>, args=args@entry=0x7f07db7fd2c0)
    at ../glib/gmessages.c:1287
#2  0x00007f09dfaada43 in g_log
    (log_domain=log_domain@entry=0x7f09e05f99ae "GStreamer", log_level=log_level@entry=G_LOG_LEVEL_CRITICAL, format=format@entry=0x7f09dfb0b320 "%s: assertion '%s' failed") at ../glib/gmessages.c:1329
#3  0x00007f09dfaaeb9d in g_return_if_fail_warning
    (log_domain=log_domain@entry=0x7f09e05f99ae "GStreamer", pretty_function=pretty_function@entry=0x7f09e0624770 <__func__.8.lto_priv.34> "gst_segment_to_stream_time", expression=expression@entry=0x7f09e06030df "segment->format == format") at ../glib/gmessages.c:3074
#4  0x00007f09e05b3c4a in gst_segment_to_stream_time (segment=segment@entry=0x557a7d94fe80, format=format@entry=GST_FORMAT_TIME, position=<optimized out>)
    at ../gst/gstsegment.c:528
#5  0x00007f094b4161b9 in volume_before_transform (base=0x557a7d94fd60 [GstVolume|volume], buffer=<optimized out>) at ../gst/volume/gstvolume.c:859
#6  0x00007f09e170d881 in gst_base_transform_chain
    (pad=pad@entry=0x557a7d950210 [GstPad|sink], parent=parent@entry=0x557a7d94fd60 [GstVolume|volume], buffer=buffer@entry=0x7f077002fea0 [GstBuffer])
    at ../libs/gst/base/gstbasetransform.c:2339
#7  0x00007f09e0594194 in gst_pad_chain_data_unchecked (pad=pad@entry=0x557a7d950210 [GstPad|sink], type=type@entry=4112, data=data@entry=0x7f077002fea0)
    at ../gst/gstpad.c:4494
#8  0x00007f09e0595046 in gst_pad_push_data (pad=pad@entry=0x557a7d94cc90 [GstPad|src], type=type@entry=4112, data=data@entry=0x7f077002fea0)
    at ../gst/gstpad.c:4770
#9  0x00007f09e0595694 in gst_pad_push (pad=0x557a7d94cc90 [GstPad|src], buffer=0x7f077002fea0 [GstBuffer]) at ../gst/gstpad.c:4889
#10 0x00007f09e170d962 in gst_base_transform_chain
    (pad=pad@entry=0x557a7d94c8b0 [GstPad|sink], parent=parent@entry=0x557a7d94c2f0 [GstAudioResample|audioresample0], buffer=buffer@entry=0x7f077002fea0 [GstBuffer]) at ../libs/gst/base/gstbasetransform.c:2391
#11 0x00007f09e0594194 in gst_pad_chain_data_unchecked (pad=pad@entry=0x557a7d94c8b0 [GstPad|sink], type=type@entry=4112, data=data@entry=0x7f077002fea0)
    at ../gst/gstpad.c:4494
#12 0x00007f09e0595046 in gst_pad_push_data (pad=pad@entry=0x557a7d947fe0 [GstPad|src], type=type@entry=4112, data=data@entry=0x7f077002fea0)
    at ../gst/gstpad.c:4770
#13 0x00007f09e0595694 in gst_pad_push (pad=0x557a7d947fe0 [GstPad|src], buffer=0x7f077002fea0 [GstBuffer]) at ../gst/gstpad.c:4889
#14 0x00007f09e170d962 in gst_base_transform_chain
    (pad=pad@entry=0x557a7d947d10 [GstPad|sink], parent=parent@entry=0x557a7d947780 [GstAudioConvert|audioconvert0], buffer=buffer@entry=0x7f077002fea0 [GstBuffer]) at ../libs/gst/base/gstbasetransform.c:2391
#15 0x00007f09e0594194 in gst_pad_chain_data_unchecked (pad=pad@entry=0x557a7d947d10 [GstPad|sink], type=type@entry=4112, data=data@entry=0x7f077002fea0)
    at ../gst/gstpad.c:4494
#16 0x00007f09e0595046 in gst_pad_push_data (pad=pad@entry=0x557a7d5e1100 [GstPad|src], type=type@entry=4112, data=data@entry=0x7f077002fea0)
    at ../gst/gstpad.c:4770
#17 0x00007f09e0595694 in gst_pad_push (pad=0x557a7d5e1100 [GstPad|src], buffer=buffer@entry=0x7f077002fea0 [GstBuffer]) at ../gst/gstpad.c:4889
#18 0x00007f094b47eb59 in gst_queue_push_one (queue=0x557a7d5e0890 [GstQueue|queue0]) at ../plugins/elements/gstqueue.c:1436
#19 gst_queue_loop (pad=<optimized out>) at ../plugins/elements/gstqueue.c:1589
#20 0x00007f09e05cf354 in gst_task_func (task=0x7f07642ad790 [GstTask|queue0:src]) at ../gst/gsttask.c:399
#21 0x00007f09dfad7832 in g_thread_pool_thread_proxy (data=<optimized out>) at ../glib/gthreadpool.c:336
#22 0x00007f09dfad71eb in g_thread_proxy (data=0x7f0960001fc0) at ../glib/gthread.c:890
#23 0x00007f09e4098e0e in start_thread (arg=<optimized out>) at pthread_create.c:447
#24 0x00007f09e411d7d4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100

[Michael Catanzaro]

(In reply to Michael Catanzaro from comment #10)
> I'm hitting this 100% of the time when viewing
> https://www.nbcnews.com/news/us-news/hannah-kobayashi-says-was-unaware-
> frenzy-family-reported-missing-rcna184463?

Um, but for some reason it only crashes when using the UI process that I currently have open. It's totally fine when I launch a new Epiphany instance to try to take a debug log. Odd.

[Michael Catanzaro]

*** Bug 265206 has been marked as a duplicate of this bug. ***

[Michael Catanzaro]

I've just marked bug #265206 as a duplicate, so when fixing this bug, we need to update the expectations for media/encrypted-media/encrypted-media-append-encrypted-unencrypted.html.

[Philippe Normand]

I can reproduce this here indeed.

[Philippe Normand]

Looks like a fdkaacdec bug, if i use the libav decoder instead there's no warning (but audio rendering is incorrect, which isn't surprising because libav).

[Michael Catanzaro]

Just hit this on one of these msnbc.com pages:

https://www.msnbc.com/top-stories/latest/alabama-redistricting-congress-voting-rights-rcna206366
https://www.msnbc.com/rachel-maddow-show/maddowblog/librarian-congress-fired-trump-newsletter-rcna206534
https://www.msnbc.com/top-stories/latest/pope-leo-free-speech-free-press-rcna206342

I'm not sure which, because all three pages crashed, and only one of the crashes was this bug. Multimedia is in rough shape currently. :(

[Philippe Normand]

This should reproduce outside of WebKit (see comment 15) so it's unlikely to be a WebKit bug.

[Michael Catanzaro]

(In reply to Philippe Normand from comment #17)
> This should reproduce outside of WebKit (see comment 15) so it's unlikely to
> be a WebKit bug.

So then next step here is to move this to fdkaac issue tracker?

I don't have enough expertise to do so myself.

[Philippe Normand]

This is quite specific to MSE so coming up with a standalone test-case doesn't look like an easy task... One of the many flush-related MSE issues. shrug :(

There are 2 issues:

- mishandling of flush in fdkaac
- mishandling of flush in volume

...