Bug 210976

Summary: media/track/track-load-error-readyState.html passes only when accompanied by some other tests
Product: WebKit Reporter: Alicia Boya García <aboya>
Component: WebKitGTKAssignee: Philippe Normand <pnormand>
Status: RESOLVED FIXED    
Severity: Normal CC: bugs-noreply, calvaris, eric.carlson, ews-watchlist, glenn, jer.noble, philipj, pnormand, sergio, tsavell
Priority: P2    
Version: WebKit Nightly Build   
Hardware: Unspecified   
OS: Unspecified   
See Also: https://bugs.webkit.org/show_bug.cgi?id=211132
https://bugs.webkit.org/show_bug.cgi?id=211133
https://bugs.webkit.org/show_bug.cgi?id=211194
Attachments:
Description Flags
Patch
none
Patch
none
Patch calvaris: review+

Description Alicia Boya García 2020-04-24 09:57:51 PDT
Ok, this is a weird one. This is media/track/track-load-error-readyState.html, the whole thing:

<!DOCTYPE html>
<html>
    <head>
        <meta http-equiv="Content-Type" content="text/html; charset=utf-8" />

        <script src=../media-file.js></script>
        <script src=../video-test.js></script>
        <script>

            function trackError()
            {
                consoleWrite("EVENT(error)");
                track = document.getElementById('testTrackError'); 
                testExpected("track.readyState", HTMLTrackElement.ERROR);
                endTest();
            }

        </script>
    </head>
    <body>
        <p>Tests the error event on HTMLTrackElement and ERROR readyState on TextTrack.</p>
        <video id="videotests">
            <track id="testTrackError" src="junk" onerror="trackError()" default>
        </video>
    </body>
</html>

Run it in a minibrowser and it will timeout every time. The onerror() handler will not be called and no text will be printed. 100% reproducible.

Run it in singly run-webkit-tests, and indeed, you will get a timeout, 100% of the time:

    $ run-webkit-tests --gtk --debug media/track/track-load-error-readyState.html
    Using port 'gtk-wk2'
    Test configuration: <, x86, debug>
    Placing test results in /webkit/WebKitBuild/Debug/layout-test-results
    Using Debug build
    Pixel tests disabled
    Regular timeout: 30000, slow test timeout: 150000
    Command line: /webkit/Tools/jhbuild/jhbuild-wrapper --gtk run /webkit/WebKitBuild/Debug/bin/WebKitTestRunner -

    Found 1 test; running 1, skipping 0.
                      
    Verbose baseline search path: platform/gtk -> platform/wk2 -> generic

    Baseline search path: platform/gtk -> platform/wk2 -> generic

    Running 1 test

    Running 1 WebKitTestRunner.     

    [1/1] media/track/track-load-error-readyState.html failed unexpectedly (test timed out, text diff)

    Retrying 1 unexpected failure ...

    Running 1 WebKitTestRunner.

    [1/1] media/track/track-load-error-readyState.html failed unexpectedly (test timed out, text diff)

    0 tests ran as expected, 1 didn't:


    Regressions: Unexpected timeouts (1)
      media/track/track-load-error-readyState.html [ Timeout ]

But here comes the surprise. Run it within certain sets of tests, and it will pass, 100% of the time. For instance:

    $ run-webkit-tests --gtk --debug media/track/track-in-band-style.html media/track/track-in-band-subtitles-too-large.html media/track/track-kind.html media/track/track-legacyapi-with-automatic-mode.html media/track/track-load-error-readyState.html
    Using port 'gtk-wk2'
    Test configuration: <, x86, debug>
    Placing test results in /webkit/WebKitBuild/Debug/layout-test-results
    Using Debug build
    Pixel tests disabled
    Regular timeout: 30000, slow test timeout: 150000
    Command line: /webkit/Tools/jhbuild/jhbuild-wrapper --gtk run /webkit/WebKitBuild/Debug/bin/WebKitTestRunner -

    Found 5 tests; running 5, skipping 0.
                      
    Verbose baseline search path: platform/gtk -> platform/wk2 -> generic

    Baseline search path: platform/gtk -> platform/wk2 -> generic

    Running 5 tests

    Running 1 WebKitTestRunner.     

    All 5 tests ran as expected.   

This is also the case when running all the tests. Therefore, according to the bots, this test passes.

I made changes to the test file to confirm that it is in fact being run. The onerror callback is called, and modifying the code there modifies the output which makes the test fail as expected.
Comment 1 Philippe Normand 2020-04-28 01:38:18 PDT
Created attachment 397820 [details]
Patch
Comment 2 Philippe Normand 2020-04-28 03:29:42 PDT
Created attachment 397824 [details]
Patch
Comment 3 Philippe Normand 2020-04-28 04:27:53 PDT
Created attachment 397827 [details]
Patch
Comment 4 Philippe Normand 2020-04-28 05:10:18 PDT
EWS should green now, please review :)
Comment 5 Philippe Normand 2020-04-28 07:17:35 PDT
Committed r260822: <https://trac.webkit.org/changeset/260822>
Comment 6 Truitt Savell 2020-04-28 09:15:31 PDT
The changes in https://trac.webkit.org/changeset/260822/webkit 

broke media/track/track-in-band-metadata-display-order.html on Mac

history:
https://results.webkit.org/?suite=layout-tests&test=media%2Ftrack%2Ftrack-in-band-metadata-display-order.html

Diff:
--- /Volumes/Data/slave/catalina-release-tests-wk1/build/layout-test-results/media/track/track-in-band-metadata-display-order-expected.txt
+++ /Volumes/Data/slave/catalina-release-tests-wk1/build/layout-test-results/media/track/track-in-band-metadata-display-order-actual.txt
@@ -15,7 +15,7 @@
 RUN(metadataTrack.addCue(new DataCue(2.25, video.duration, "second data cue")))
 RUN(video.currentTime = 3)
 EVENT(seeked)
-EXPECTED (textTrackDisplayElement(video, "display", 0).textContent == 'I am later') OK
-EXPECTED (textTrackDisplayElement(video, "display", 1).textContent == 'I am earlier') OK
+EXPECTED (textTrackDisplayElement(video, "display", 0).textContent == 'I am later'), OBSERVED 'I am later ::cue{background-color:rgba(0, 0, 0, 0) !important;color:#ffffff;font-family: "Helvetica";} ::-webkit-media-text-track-display-backdrop{background-color:rgba(0, 0, 0, 0.498) !important;padding: .4em !important;border-radius:8px !important;}' FAIL
+EXPECTED (textTrackDisplayElement(video, "display", 1).textContent == 'I am earlier'), OBSERVED 'I am earlier ::cue{background-color:rgba(0, 0, 0, 0) !important;color:#ffffff;font-family: "Helvetica";} ::-webkit-media-text-track-display-backdrop{background-color:rgba(0, 0, 0, 0.498) !important;padding: .4em !important;border-radius:8px !important;}' FAIL
 END OF TEST
Comment 7 Eric Carlson 2020-04-28 09:19:52 PDT
Comment on attachment 397827 [details]
Patch

Nice fix, thanks!
Comment 8 Philippe Normand 2020-04-28 09:34:39 PDT
Comment on attachment 397827 [details]
Patch

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

> LayoutTests/media/track/track-load-error-readyState.html:15
> +            function setup()
> +            {
> +                if (window.internals)
> +                    run("internals.setCaptionDisplayMode('Automatic')");
> +            }
> +

Truitt, the test would need a similar setup function. I wonder why the EWS didn't fail on that test?
Comment 9 Truitt Savell 2020-04-28 09:44:48 PDT
(In reply to Philippe Normand from comment #8)
> Comment on attachment 397827 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=397827&action=review
> 
> > LayoutTests/media/track/track-load-error-readyState.html:15
> > +            function setup()
> > +            {
> > +                if (window.internals)
> > +                    run("internals.setCaptionDisplayMode('Automatic')");
> > +            }
> > +
> 
> Truitt, the test would need a similar setup function. I wonder why the EWS
> didn't fail on that test?

Looks like our test history doesn't show any failures for that test: https://results.webkit.org/?suite=layout-tests&test=media%2Ftrack%2Ftrack-load-error-readyState.html
Comment 10 Philippe Normand 2020-04-28 10:10:59 PDT
Comment on attachment 397827 [details]
Patch

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

>>> LayoutTests/media/track/track-load-error-readyState.html:15
>>> +
>> 
>> Truitt, the test would need a similar setup function. I wonder why the EWS didn't fail on that test?
> 
> Looks like our test history doesn't show any failures for that test: https://results.webkit.org/?suite=layout-tests&test=media%2Ftrack%2Ftrack-load-error-readyState.html

I meant for the test now failing after this patch landed... Anyway, please review #211133 :)
Comment 11 Truitt Savell 2020-04-29 10:48:45 PDT
I just found this test is also failing after r260822

media/track/track-cue-missing.html

History:
https://results.webkit.org/?suite=layout-tests&test=media%2Ftrack%2Ftrack-cue-missing.html

Diff:
--- /Volumes/Data/slave/catalina-debug-tests-wk2/build/layout-test-results/media/track/track-cue-missing-expected.txt
+++ /Volumes/Data/slave/catalina-debug-tests-wk2/build/layout-test-results/media/track/track-cue-missing-actual.txt
@@ -5,6 +5,6 @@
 EVENT(loadeddata)
 Created 121 cues.
 EVENT(ended)
-EXPECTED (missedCueCount < '50') OK
+EXPECTED (missedCueCount < '50'), OBSERVED '56' FAIL
 END OF TEST
Comment 12 Philippe Normand 2020-04-29 10:52:08 PDT
Another test flagged as failing in GTK... I'm checking it now. Thanks Truitt.
Comment 13 Truitt Savell 2020-04-29 14:19:33 PDT
(In reply to Truitt Savell from comment #11)
> I just found this test is also failing after r260822
> 
> media/track/track-cue-missing.html
> 
> History:
> https://results.webkit.org/?suite=layout-tests&test=media%2Ftrack%2Ftrack-
> cue-missing.html
> 
> Diff:
> ---
> /Volumes/Data/slave/catalina-debug-tests-wk2/build/layout-test-results/media/
> track/track-cue-missing-expected.txt
> +++
> /Volumes/Data/slave/catalina-debug-tests-wk2/build/layout-test-results/media/
> track/track-cue-missing-actual.txt
> @@ -5,6 +5,6 @@
>  EVENT(loadeddata)
>  Created 121 cues.
>  EVENT(ended)
> -EXPECTED (missedCueCount < '50') OK
> +EXPECTED (missedCueCount < '50'), OBSERVED '56' FAIL
>  END OF TEST

I was able to reproduce it using command:
run-webkit-tests  media/track/track-cue-missing.html --iterations 2000 --exit-after-n-failures 1 -f --debug

on a build of r260823

I cannot reproduce this on a build of r260820
sense r260823 is a test gardening change that leaves r260822 and r260821 as where this regressed