LayoutTest media/modern-media-controls/airplay-button/airplay-button.html is a flaky timeout https://build.webkit.org/results/Apple%20Sierra%20Debug%20WK1%20(Tests)/r212417%20(3232)/results.html https://webkit-test-results.webkit.org/dashboards/flakiness_dashboard.html#showAllRuns=true&tests=media%2Fmodern-media-controls%2Fairplay-button%2Fairplay-button.html
Marked test as flaky on mac-wk1 in http://trac.webkit.org/projects/webkit/changeset/212480
<rdar://problem/30799198>
Created attachment 303164 [details] Patch
Comment on attachment 303164 [details] Patch Clearing flags on attachment: 303164 Committed r213263: <http://trac.webkit.org/changeset/213263>
All reviewed patches have been landed. Closing bug.
This test has timed out 3 times today on mac-wk1. Reopening.
Created attachment 303825 [details] Patch
Comment on attachment 303825 [details] Patch View in context: https://bugs.webkit.org/attachment.cgi?id=303825&action=review > LayoutTests/media/modern-media-controls/airplay-button/airplay-button.html:27 > +airplayButton._image.addEventListener("load", event => { Will this image always be not-yet-loaded when this code runs?
(In reply to comment #8) > Comment on attachment 303825 [details] > Patch > > View in context: > https://bugs.webkit.org/attachment.cgi?id=303825&action=review > > > LayoutTests/media/modern-media-controls/airplay-button/airplay-button.html:27 > > +airplayButton._image.addEventListener("load", event => { > > Will this image always be not-yet-loaded when this code runs? On a first run, it should be, yes. On a re-run, it won't. But bots will always be in the first case.
Comment on attachment 303825 [details] Patch Clearing flags on attachment: 303825 Committed r213595: <http://trac.webkit.org/changeset/213595>
Reopenng since the last patch was only about adding more assertions for more detailed logging but likely not fixing the overall issue.
I marked the test as pass/fail in http://trac.webkit.org/projects/webkit/changeset/213604 because it was making the bots red.
OK, so with the additional logging, we have an interesting timeout here: https://build.webkit.org/results/Apple%20El%20Capitan%20Debug%20WK1%20(Tests)/r213599%20(12043)/media/modern-media-controls/airplay-button/airplay-button-pretty-diff.html PASS airplayButton.element.classList.contains("icon") is true PASS airplayButton.element.classList.contains("airplay") is true PASS airplayButton.iconName is "airplay" -PASS airplayButton.width is 0 -PASS airplayButton.height is 0 +FAIL airplayButton.width should be 0. Was 25. +FAIL airplayButton.height should be 0. Was 22. PASS airplayButton._image is iconService.imageForIconNameAndLayoutTraits(Icons.Airplay, LayoutTraits.macOS) PASS airplayButton._image.src is not "" -PASS airplayButton._image.complete is false +FAIL airplayButton._image.complete should be false. Was true. PASS airplayButton.width is not 0 PASS airplayButton.height is not 0 PASS airplayButton.needsLayout is true PASS scheduler.hasScheduledLayoutCallbacks is true -PASS airplayButton.element.style.webkitMaskImage.includes("macOS/airplay@") became true -PASS macOSFullscreenAirplayButton.element.style.webkitMaskImage.includes("macOS/airplay-fullscreen@") became true -PASS iOSAirplayButton.element.style.webkitMaskImage.includes("iOS/airplay@") became true So, the "load" event is dispatched on button's image, since the new assertions that happen during that event are reached. However, this assertions times out: shouldBecomeEqual('airplayButton.element.style.webkitMaskImage.includes("macOS/airplay@")', "true", …) So… _updateImage() is called but somehow we're not getting the right properties committed and the CSS change never happens.
Created attachment 303919 [details] Patch
Comment on attachment 303919 [details] Patch rs=me
Comment on attachment 303919 [details] Patch Clearing flags on attachment: 303919 Committed r213642: <http://trac.webkit.org/changeset/213642>
So with the new logging the state looks as expected but somehow the rAF call that is scheduled never completes. There's still a chance that for some reason we are causing the rAF call to be canceled. I'll add some more logging so we can see what's wrong. The other reason might be that the rAF call, for other reasons outside of the MMC codebase, never happens.
Actually, looking at the code some more, we never unregister rAF calls. Something is terribly wrong here, and I don't have any evidence that this is a failure in the MMC codebase.
Created attachment 304036 [details] Patch for landing
Comment on attachment 304036 [details] Patch for landing Clearing flags on attachment: 304036 Committed r213706: <http://trac.webkit.org/changeset/213706>
Reopening since we're only adding additional assertions.
So it's clear now that this is a WebCore issues, somehow the rAF callback is never fired. See: https://build.webkit.org/results/Apple%20El%20Capitan%20Debug%20WK1%20(Tests)/r213765%20(12124)/media/modern-media-controls/airplay-button/airplay-button-pretty-diff.html https://build.webkit.org/results/Apple%20Sierra%20Release%20WK1%20(Tests)/r213769%20(4414)/media/modern-media-controls/airplay-button/airplay-button-pretty-diff.html Will reach out to some people to try to understand how this could possibly happen.
Marked test as a flaky timeout on mac-wk1 in http://trac.webkit.org/projects/webkit/changeset/214050
The next step will be to add some logging in WebCore to try to understand why the rAF callback isn't being fired.
Created attachment 305619 [details] Patch
Comment on attachment 305619 [details] Patch View in context: https://bugs.webkit.org/attachment.cgi?id=305619&action=review > Source/WebCore/dom/ScriptedAnimationController.cpp:341 > +{ > + m_document->dispatchEvent(Event::create(type, false, false)); > +} What about the if (m_shouldDispatchEvents) ?
Comment on attachment 305619 [details] Patch Attachment 305619 [details] did not pass mac-ews (mac): Output: http://webkit-queues.webkit.org/results/3428448 New failing tests: fast/animation/request-animation-frame-detach-element.html fast/animation/request-animation-frame-detach-element2.html
Created attachment 305627 [details] Archive of layout-test-results from ews100 for mac-elcapitan The attached test failures were seen while running run-webkit-tests on the mac-ews. Bot: ews100 Port: mac-elcapitan Platform: Mac OS X 10.11.6
Comment on attachment 305619 [details] Patch Attachment 305619 [details] did not pass mac-wk2-ews (mac-wk2): Output: http://webkit-queues.webkit.org/results/3428510 New failing tests: fast/animation/request-animation-frame-detach-element.html fast/animation/request-animation-frame-detach-element2.html
Created attachment 305630 [details] Archive of layout-test-results from ews105 for mac-elcapitan-wk2 The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews. Bot: ews105 Port: mac-elcapitan-wk2 Platform: Mac OS X 10.11.6
Comment on attachment 305619 [details] Patch Attachment 305619 [details] did not pass mac-debug-ews (mac): Output: http://webkit-queues.webkit.org/results/3428483 New failing tests: fast/animation/request-animation-frame-detach-element.html fast/animation/request-animation-frame-detach-element2.html
Created attachment 305632 [details] Archive of layout-test-results from ews113 for mac-elcapitan The attached test failures were seen while running run-webkit-tests on the mac-debug-ews. Bot: ews113 Port: mac-elcapitan Platform: Mac OS X 10.11.6
Comment on attachment 305619 [details] Patch Attachment 305619 [details] did not pass ios-sim-ews (ios-simulator-wk2): Output: http://webkit-queues.webkit.org/results/3428668 New failing tests: fast/animation/request-animation-frame-detach-element.html fast/animation/request-animation-frame-detach-element2.html
Created attachment 305637 [details] Archive of layout-test-results from ews123 for ios-simulator-wk2 The attached test failures were seen while running run-webkit-tests on the ios-sim-ews. Bot: ews123 Port: ios-simulator-wk2 Platform: Mac OS X 10.11.6
Created attachment 305648 [details] Patch
../../Source/WebCore/dom/ScriptedAnimationController.h:99:10: note: initializing argument 1 of 'void WebCore::ScriptedAnimationController::dispatchLoggingEventIfRequired(const int&)' ../../Source/WebCore/dom/ScriptedAnimationController.cpp:202:69: error: invalid conversion from 'const char*' to 'int' [-fpermissive]
Comment on attachment 305648 [details] Patch View in context: https://bugs.webkit.org/attachment.cgi?id=305648&action=review > Source/WebCore/dom/ScriptedAnimationController.cpp:84 > + dispatchLoggingEventIfRequired("raf-suspend"); GTK is failing because this function expects an AtomicString, not a char*. You either want something like AtomicString("raf-suspend", AtomicString::ConstructFromLiteral) or ASCIILiteral("raf-suspend") (which itself will do a conversion)
Created attachment 305657 [details] Patch
Comment on attachment 305657 [details] Patch Attachment 305657 [details] did not pass mac-debug-ews (mac): Output: http://webkit-queues.webkit.org/results/3429927 New failing tests: fast/animation/request-animation-frame-detach-element.html fast/animation/request-animation-frame-detach-element2.html fast/animation/request-animation-frame-remove-client.html
Created attachment 305676 [details] Archive of layout-test-results from ews117 for mac-elcapitan The attached test failures were seen while running run-webkit-tests on the mac-debug-ews. Bot: ews117 Port: mac-elcapitan Platform: Mac OS X 10.11.6
Comment on attachment 305657 [details] Patch Attachment 305657 [details] did not pass mac-ews (mac): Output: http://webkit-queues.webkit.org/results/3430091 New failing tests: fast/animation/request-animation-frame-detach-element.html fast/animation/request-animation-frame-detach-element2.html
Created attachment 305679 [details] Archive of layout-test-results from ews103 for mac-elcapitan The attached test failures were seen while running run-webkit-tests on the mac-ews. Bot: ews103 Port: mac-elcapitan Platform: Mac OS X 10.11.6
Comment on attachment 305657 [details] Patch Attachment 305657 [details] did not pass ios-sim-ews (ios-simulator-wk2): Output: http://webkit-queues.webkit.org/results/3430118 New failing tests: fast/animation/request-animation-frame-detach-element.html fast/animation/request-animation-frame-detach-element2.html
Created attachment 305683 [details] Archive of layout-test-results from ews126 for ios-simulator-wk2 The attached test failures were seen while running run-webkit-tests on the ios-sim-ews. Bot: ews126 Port: ios-simulator-wk2 Platform: Mac OS X 10.11.6
Comment on attachment 305657 [details] Patch Attachment 305657 [details] did not pass mac-wk2-ews (mac-wk2): Output: http://webkit-queues.webkit.org/results/3430337 New failing tests: fast/animation/request-animation-frame-detach-element.html fast/animation/request-animation-frame-detach-element2.html
Created attachment 305684 [details] Archive of layout-test-results from ews105 for mac-elcapitan-wk2 The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews. Bot: ews105 Port: mac-elcapitan-wk2 Platform: Mac OS X 10.11.6
Created attachment 305710 [details] Patch
Created attachment 305713 [details] Patch
Created attachment 305714 [details] Patch
Created attachment 305716 [details] Patch for landing
Comment on attachment 305716 [details] Patch for landing Clearing flags on attachment: 305716 Committed r214532: <http://trac.webkit.org/changeset/214532>
Reopening since we only added logging.
The addition of ScriptedAnimationController reveals the issue, ScriptedAnimationController gets suspended: https://build.webkit.org/results/Apple%20Sierra%20Debug%20WK1%20(Tests)/r214547%20(229)/media/modern-media-controls/airplay-button/airplay-button-pretty-diff.html https://build.webkit.org/results/Apple%20Sierra%20Debug%20WK1%20(Tests)/r214536%20(226)/media/modern-media-controls/airplay-button/airplay-button-pretty-diff.html https://build.webkit.org/results/Apple%20Sierra%20Debug%20WK1%20(Tests)/r214598%20(247)/media/modern-media-controls/airplay-button/airplay-button-pretty-diff.html All of those show a call to suspend() right before registerCallback() is called, and as a result scheduleAnimation() is never called. There are two call sites for ScriptedAnimationController::suspend(), Document::suspendScriptedAnimationControllerCallbacks() and Document::requestAnimationFrame() in case there's no page or animations are suspended on that page when we're trying to create the ScriptedAnimationController.
The logging seems to indicate that it's the call to requestAnimationFrame() from JS that triggers the call to suspend() through Document::requestAnimationFrame(). We're likely hitting this condition: // It's possible that the Page may have suspended scripted animations before // we were created. We need to make sure that we don't start up the animation // controller on a background tab, for example. if (!page() || page()->scriptedAnimationsSuspended()) m_scriptedAnimationController->suspend(); I'll add more logging to figure out if that's correct and which of those conditions are true.
Created attachment 305859 [details] Patch for landing
Comment on attachment 305859 [details] Patch for landing Clearing flags on attachment: 305859 Committed r214603: <http://trac.webkit.org/changeset/214603>
Reopening since the last patch was just providing more logging.
Created attachment 305944 [details] Patch for landing
Comment on attachment 305944 [details] Patch for landing Rejecting attachment 305944 [details] from commit-queue. Failed to run "['/Volumes/Data/EWS/WebKit/Tools/Scripts/webkit-patch', '--status-host=webkit-queues.webkit.org', '--bot-id=webkit-cq-01', 'validate-changelog', '--check-oops', '--non-interactive', 305944, '--port=mac']" exit_code: 1 cwd: /Volumes/Data/EWS/WebKit /Volumes/Data/EWS/WebKit/LayoutTests/ChangeLog neither lists a valid reviewer nor contains the string "Unreviewed" or "Rubber stamp" (case insensitive). Full output: http://webkit-queues.webkit.org/results/3446233
Created attachment 305951 [details] Patch for landing
Some comments on IRC from Alexey about past changes related to throttling or suspending animations: ap: graouts: looking for changes in history... ap: graouts: not the one I was thinking of, but related: https://trac.webkit.org/r184807 ap: graouts: more related, http://trac.webkit.org/r183488 ap: graouts: multiple related fixes in https://bugs.webkit.org/show_bug.cgi?id=144155 ap: graouts: and https://bugs.webkit.org/show_bug.cgi?id=147718
Comment on attachment 305951 [details] Patch for landing Clearing flags on attachment: 305951 Committed r214659: <http://trac.webkit.org/changeset/214659>
Reopening since commit was to add logging only.
So it's definitely the page()->scriptedAnimationsSuspended() condition that causes the call to requestAnimationFrame() to suspend the ScriptedAnimationController. However, the call to Page::suspendScriptedAnimations() must happen before we set internals.settings.setShouldDispatchRequestAnimationFrameEvents(true) because we don't see the backtrace for the call to Page::suspendScriptedAnimations(). https://build.webkit.org/results/Apple%20Sierra%20Debug%20WK1%20(Tests)/r214699%20(292)/media/modern-media-controls/airplay-button/airplay-button-pretty-diff.html
Created attachment 310887 [details] Patch
Comment on attachment 310887 [details] Patch View in context: https://bugs.webkit.org/attachment.cgi?id=310887&action=review > Source/WebCore/page/Page.cpp:1146 > + WTFReportBacktrace(); You might want to WTFLogAlways() something just before this so people know why you're logging backtraces.
Created attachment 310899 [details] Patch for landing
Comment on attachment 310899 [details] Patch for landing Clearing flags on attachment: 310899 Committed r217239: <http://trac.webkit.org/changeset/217239>
(In reply to Simon Fraser (smfr) from comment #73) > Comment on attachment 310887 [details] > Patch > > View in context: > https://bugs.webkit.org/attachment.cgi?id=310887&action=review > > > Source/WebCore/page/Page.cpp:1146 > > + WTFReportBacktrace(); > > You might want to WTFLogAlways() something just before this so people know > why you're logging backtraces. It looks like logging these backtraces has caused performance tests to fail due to the unexpected output: https://build.webkit.org/builders/Apple%20El%20Capitan%20Release%20WK2%20(Perf)/builds/466
I see the logging in the stdio for this LayoutTest run, not sure if it is what you were hoping for: https://build.webkit.org/builders/Apple%20El%20Capitan%20Debug%20WK1%20(Tests)/builds/1383
Thanks for tackling this issue; I've been seeing assertions relating to this code for some time. Unfortunately this broke the GTK+ layout test bot really badly: it's not uploading results at all anymore. Anyway, you achieved the desired effect of figuring out what layout tests cause this, because we have a detailed log: https://build.webkit.org/builders/GTK%20Linux%2064-bit%20Release%20(Tests)/builds/1292/steps/layout-test/logs/stdio It's currently crashing on this (excepted from that log): 14:41:59.836 32412 worker/1: UnicodeEncodeError(''ascii' codec can't encode character u'\u2013' in position 119: ordinal not in range(128)') raised: 14:41:59.842 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/common/message_pool.py", line 255, in run 14:41:59.842 32412 worker.handle(message.name, message.src, *message.args) 14:41:59.842 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/layout_tests/controllers/layout_test_runner.py", line 259, in handle 14:41:59.842 32412 self._run_test(test_input, test_list_name) 14:41:59.842 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/layout_tests/controllers/layout_test_runner.py", line 283, in _run_test 14:41:59.842 32412 result = self._run_test_with_or_without_timeout(test_input, test_timeout_sec, stop_when_done) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/layout_tests/controllers/layout_test_runner.py", line 326, in _run_test_with_or_without_timeout 14:41:59.843 32412 return self._run_test_in_this_thread(test_input, stop_when_done) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/layout_tests/controllers/layout_test_runner.py", line 407, in _run_test_in_this_thread 14:41:59.843 32412 return self._run_single_test(self._driver, test_input, stop_when_done) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/layout_tests/controllers/layout_test_runner.py", line 411, in _run_single_test 14:41:59.843 32412 self._name, driver, test_input, stop_when_done) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/layout_tests/controllers/single_test_runner.py", line 46, in run_single_test 14:41:59.843 32412 return runner.run() 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/layout_tests/controllers/single_test_runner.py", line 105, in run 14:41:59.843 32412 return self._run_compare_test() 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/layout_tests/controllers/single_test_runner.py", line 108, in _run_compare_test 14:41:59.843 32412 driver_output = self._driver.run_test(self._driver_input(), self._stop_when_done) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/port/driver.py", line 680, in run_test 14:41:59.843 32412 return self._driver.run_test(driver_input, stop_when_done) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/port/driver.py", line 227, in run_test 14:41:59.843 32412 self.error_from_test, crash_log = self._get_crash_log(text, self.error_from_test, newer_than=start_time) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/port/driver.py", line 244, in _get_crash_log 14:41:59.843 32412 return self._port._get_crash_log(self._crashed_process_name, self._crashed_pid, stdout, stderr, newer_than) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/port/gtk.py", line 225, in _get_crash_log 14:41:59.843 32412 return GDBCrashLogGenerator(name, pid, newer_than, self._filesystem, self._path_to_driver).generate_crash_log(stdout, stderr) 14:41:59.843 32412 File "/home/slave/webkitgtk/gtk-linux-64-release-tests/build/Tools/Scripts/webkitpy/port/linux_get_crash_log.py", line 76, in generate_crash_log 14:41:59.843 32412 errors_str = cppfilt_proc.communicate(errors_str)[0] 14:41:59.843 32412 File "/usr/lib/python2.7/subprocess.py", line 799, in communicate 14:41:59.843 32412 return self._communicate(input) 14:41:59.843 32412 File "/usr/lib/python2.7/subprocess.py", line 1409, in _communicate 14:41:59.843 32412 stdout, stderr = self._communicate_with_poll(input) 14:41:59.843 32412 File "/usr/lib/python2.7/subprocess.py", line 1473, in _communicate_with_poll 14:41:59.843 32412 input_offset += os.write(fd, chunk) I'm tempted to roll this out, but first I'll try a speculative fix. I bet the text "Page::suspendScriptedAnimations() – webkit.org/b/168409" is what's breaking the text runner. I will try changing the Unicode – to an ASCII hyphen -.
Committed r217263: <http://trac.webkit.org/changeset/217263>
The bot is reporting results again, so that did the trick. We should make the test runner not fail when it sees Unicode.
(In reply to Ryan Haddad from comment #77) > It looks like logging these backtraces has caused performance tests to fail > due to the unexpected output: > https://build.webkit.org/builders/ > Apple%20El%20Capitan%20Release%20WK2%20(Perf)/builds/466 Hopefully I'll be able to remove them sometime today when we can see this test timing out and can see what's happening that might cause this based on the backtraces.
(In reply to Antoine Quint from comment #82) > (In reply to Ryan Haddad from comment #77) > > It looks like logging these backtraces has caused performance tests to fail > > due to the unexpected output: > > https://build.webkit.org/builders/ > > Apple%20El%20Capitan%20Release%20WK2%20(Perf)/builds/466 > > Hopefully I'll be able to remove them sometime today when we can see this > test timing out and can see what's happening that might cause this based on > the backtraces. It doesn't seem like the test has timed out. I don't think we should leave perf tests broken any longer.
Reopening to attach new patch.
Created attachment 311108 [details] Patch for landing
(In reply to Ryan Haddad from comment #83) > It doesn't seem like the test has timed out. I don't think we should leave > perf tests broken any longer. I agree, just sent a patch out to turn the logging off.
Comment on attachment 311108 [details] Patch for landing Clearing flags on attachment: 311108 Committed r217348: <http://trac.webkit.org/changeset/217348>
This test has been rebaselined for the latest modern media controls codebase and yet it started timing out again, on Sierra Debug WK1 only for now. At this point I think we should expose a way to explicitly unsuspend rAF through Internals for modern-media-controls tests.
Reopened due to recent flakiness.
Marked as flaky in https://trac.webkit.org/changeset/217880/webkit.
https://bugs.webkit.org/show_bug.cgi?id=173326 will be adding extra logging to hopefully finally understand the root cause of this.
The flakiness may be caused by https://bugs.webkit.org/show_bug.cgi?id=173485.
Alas, we're stil hitting this issue, adding more, targeted logging in https://bugs.webkit.org/show_bug.cgi?id=173626.
*** Bug 173620 has been marked as a duplicate of this bug. ***
Let's close this, and track the issue with https://bugs.webkit.org/show_bug.cgi?id=173628 instead.