Bug 229219 - [GLIB][GStreamer] test http/tests/security/webaudio-render-remote-audio-allowed-crossorigin-redirect.html is a flaky timeout since r278004
Summary: [GLIB][GStreamer] test http/tests/security/webaudio-render-remote-audio-allow...
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Media (show other bugs)
Version: WebKit Nightly Build
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Enrique Ocaña
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2021-08-17 19:11 PDT by Arcady Goldmints-Orlov
Modified: 2021-10-18 11:13 PDT (History)
12 users (show)

See Also:


Attachments
Gardening Patch (1.52 KB, patch)
2021-08-17 19:14 PDT, Arcady Goldmints-Orlov
no flags Details | Formatted Diff | Diff
Patch (5.46 KB, patch)
2021-10-06 11:24 PDT, Enrique Ocaña
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Arcady Goldmints-Orlov 2021-08-17 19:11:47 PDT
The changes in r278004 appear to be causing this test to timeout, but only some of the time.
Comment 1 Arcady Goldmints-Orlov 2021-08-17 19:14:22 PDT
Created attachment 435734 [details]
Gardening Patch
Comment 2 EWS 2021-08-17 20:30:12 PDT
Committed r281179 (240625@main): <https://commits.webkit.org/240625@main>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 435734 [details].
Comment 3 Radar WebKit Bug Importer 2021-08-17 20:31:18 PDT
<rdar://problem/82059333>
Comment 4 Arcady Goldmints-Orlov 2021-08-17 20:50:13 PDT
Reopening to track the fix for this issue.
Comment 5 Enrique Ocaña 2021-10-06 11:24:56 PDT
Created attachment 440395 [details]
Patch
Comment 6 Philippe Normand 2021-10-06 12:21:51 PDT
Comment on attachment 440395 [details]
Patch

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

> Source/WebCore/platform/audio/gstreamer/AudioSourceProviderGStreamer.cpp:325
> +    // Some intermediate bins are eating up the EOS message posted to the bus of the inner bin that

I wonder if setting the message-forward property to TRUE on m_audioSinkBin could help with that? Have you tried it?
Comment 7 Enrique Ocaña 2021-10-07 00:59:30 PDT
Comment on attachment 440395 [details]
Patch

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

>> Source/WebCore/platform/audio/gstreamer/AudioSourceProviderGStreamer.cpp:325
>> +    // Some intermediate bins are eating up the EOS message posted to the bus of the inner bin that
> 
> I wonder if setting the message-forward property to TRUE on m_audioSinkBin could help with that? Have you tried it?

I had tried that before, but it wasn't successful and I didn't committed the code on my work branch, so I couldn't recheck now to answer your comment.

I've just written code now to not only set message-forward on m_audioSinkBin, but also on any other parent bin up to the topmost GstPlaybin element, and I ensured that the property was properly set by checking the pipeline dumps. Still, the GST_MESSAGE_EOS isn't received by MediaPlayerPrivateGStreamer::handleMessage().
Comment 8 Philippe Normand 2021-10-07 08:45:09 PDT
Per the doc, you should receive "element" messages on the bus:

  /**
   * GstBin:message-forward:
   *
   * Forward all children messages, even those that would normally be filtered by
   * the bin. This can be interesting when one wants to be notified of the EOS
   * state of individual elements, for example.
   *
   * The messages are converted to an ELEMENT message with the bin as the
   * source. The structure of the message is named `GstBinForwarded` and contains
   * a field named `message` that contains the original forwarded #GstMessage.
   */
Comment 9 Enrique Ocaña 2021-10-14 05:44:52 PDT
I'm only able to receive the forwarded message (as an element message, as you pointed) only in the case where the test was already succeeding (with gst logs enabled here). In the case where the test fails (with gst logs disabled here) I don't get it. Enabling and disabling logs has some influence in the reproducibility of this problem, so if must be some race condition buried deep somewhere in GStreamer.

I added some debug printfs. I just print "EOS" when appsink emits EOS, but I've disabled the code to forward it to the main pipeline (the code in my previously submitted patch). The code to enable message-forward in all the bins up to GstPipeline was added. This log is from the successful case:

### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from autoaudiosink1
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from audio-sink
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from abin
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from playsink
### WebCore::AudioSourceProviderGStreamer::handleNewDeinterleavePad(GstPad*)::<lambda(GstElement*, GstElement*)>: EOS
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message eos from appsink1
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message eos from autoaudiosink1
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message eos from audio-sink
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message eos from abin
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message eos from playsink
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): media-player-0 has EOS
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GST_MESSAGE_EOS

This other log is from the failing case:

### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from autoaudiosink1
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from audio-sink
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from abin
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from playsink
### WebCore::AudioSourceProviderGStreamer::handleNewDeinterleavePad(GstPad*)::<lambda(GstElement*, GstElement*)>: EOS
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message eos from appsink1
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-start from autoaudiosink1
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-start from audio-sink
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-start from abin
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-start from playsink
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from autoaudiosink1
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from audio-sink
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from abin
### void WebCore::MediaPlayerPrivateGStreamer::handleMessage(GstMessage*): GstBinForwarded element message async-done from playsink

As you see, relying on message-forward isn't enough.
Comment 10 EWS 2021-10-18 04:33:46 PDT
Committed r284365 (243150@main): <https://commits.webkit.org/243150@main>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 440395 [details].
Comment 11 Arcady Goldmints-Orlov 2021-10-18 10:37:28 PDT
Since the test is a flake, I will take a look at the next few test runs to confirm before I remove it from the expectations.
Comment 12 Enrique Ocaña 2021-10-18 11:13:08 PDT
(In reply to Arcady Goldmints-Orlov from comment #11)
> Since the test is a flake, I will take a look at the next few test runs to
> confirm before I remove it from the expectations.

Argh! I forgot to remove the flake from the expectations. I'm almost sure that now it's not a flake anymore, but better have a look to it for a while, yes. Thanks!