Closed Bug 1374790 Opened 3 years ago Closed Last year

Intermittent layout/generic/test/test_bug784410.html | Test timed out.

Categories

(Core :: Layout, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla65
Tracking Status
firefox64 --- fixed
firefox65 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: kats)

Details

(Keywords: bulk-close-intermittents, intermittent-failure, Whiteboard: [stockwell fixed])

Attachments

(1 file)

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=203678908&repo=mozilla-central&lineNumber=1594

[task 2018-10-05T16:07:45.483Z] 16:07:45     INFO - TEST-PASS | layout/generic/test/test_bug784410.html | Outer element should have scrolled down 
[task 2018-10-05T16:07:45.484Z] 16:07:45     INFO - Buffered messages finished
[task 2018-10-05T16:07:45.486Z] 16:07:45     INFO - TEST-UNEXPECTED-FAIL | layout/generic/test/test_bug784410.html | Test timed out. 
[task 2018-10-05T16:07:45.487Z] 16:07:45     INFO -     reportError@SimpleTest/TestRunner.js:121:7
[task 2018-10-05T16:07:45.488Z] 16:07:45     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2018-10-05T16:07:45.489Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.490Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.491Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.491Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.492Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.492Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.492Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.492Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.492Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.492Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.492Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.492Z] 16:07:45     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO -     TestRunner.runTests/<@SimpleTest/TestRunner.js:381:9
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO -     promise callback*TestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO -     RunSet.runtests@SimpleTest/setup.js:194:3
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO -     RunSet.runall@SimpleTest/setup.js:173:5
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO -     hookupTests@SimpleTest/setup.js:266:5
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO -     hookup@SimpleTest/setup.js:246:5
[task 2018-10-05T16:07:45.493Z] 16:07:45     INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2018-10-05T16:07:46.139Z] 16:07:46     INFO - GECKO(1076) | MEMORY STAT | vsize 20973460MB | residentFast 760MB
Status: RESOLVED → REOPENED
QA Contact: svoisen
Resolution: INCOMPLETE → ---
QA Contact: svoisen
This bug failed 33 times in the last 7 days. Occurs windows10-64-qr on opt.

Log:
https://treeherder.mozilla.org/logviewer.html#?job_id=206749172&repo=mozilla-inbound&lineNumber=8281

INFO - TEST-START | layout/generic/test/test_bug784410.html
05:56:54     INFO - TEST-INFO | started process screenshot
05:56:54     INFO - TEST-INFO | screenshot: exit 0
05:56:54     INFO - Buffered messages logged at 05:51:41
05:56:54     INFO - must wait for load
05:56:54     INFO - TEST-PASS | layout/generic/test/test_bug784410.html | Inner element should not have scrolled down 
05:56:54     INFO - TEST-PASS | layout/generic/test/test_bug784410.html | Outer element should have scrolled down 
05:56:54     INFO - Buffered messages finished
05:56:54     INFO - TEST-UNEXPECTED-FAIL | layout/generic/test/test_bug784410.html | Test timed out. 
05:56:54     INFO -     reportError@SimpleTest/TestRunner.js:121:7
05:56:54     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
05:56:54     INFO -     TestRunner.runTests/<@SimpleTest/TestRunner.js:381:9
05:56:54     INFO -     promise callback*TestRunner.runTests@SimpleTest/TestRunner.js:368:50
05:56:54     INFO -     RunSet.runtests@SimpleTest/setup.js:201:3
05:56:54     INFO -     RunSet.runall@SimpleTest/setup.js:180:5
05:56:54     INFO -     hookupTests@SimpleTest/setup.js:273:5
05:56:54     INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
05:56:54     INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
05:56:54     INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
05:56:54     INFO -     hookup@SimpleTest/setup.js:253:5
05:56:54     INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Ctask_1540012932%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
05:56:55     INFO - GECKO(10504) | MEMORY STAT | vsize 1522MB | vsizeMaxContiguous 132277436MB | residentFast 103MB | heapAllocated 14MB
05:56:55     INFO - TEST-OK | layout/generic/test/test_bug784410.html | took 313599ms

svoisen: Can you please take a look at this bug?
Flags: needinfo?(svoisen)
Whiteboard: [stockwell needswork]
Mats: Any ideas on the increase in failures here? (Pinging you since it looks like you - once upon a time - reviewed the fix for bug this tests against.)
Flags: needinfo?(svoisen) → needinfo?(mats)
Maybe bug 1488871 affected this test somehow?
kats / tnikkel probably knows more about how this test works...
Flags: needinfo?(tnikkel)
Flags: needinfo?(mats)
Flags: needinfo?(kats)
(In reply to Mats Palmgren (:mats) from comment #37)
> Maybe bug 1488871 affected this test somehow?

There seems to be a big spike from Oct 16 - Oct 19, which doesn't seem to correspond to any activity on bug 1488871.

> kats / tnikkel probably knows more about how this test works...

Not really, although it doesn't seem super complicated. It looks like the test synthesizes a keyboard scroll, which seems to work since the first part of doneScroll() runs and passes checks. I suspect the second part (which synthesizes an APZ wheel scroll) also executes, but then the scroll doesn't happen. To see why, check out the screenshot of the failure - it's just a tab switch spinner. Having the tab switch spinner up means the compositor doesn't yet have all the necessary info, and so APZ will probably just discard the wheel scroll.

I'm going to do some backfilling to see when the Oct 16 spike really started, hopefully that will give us a culprit.
Flags: needinfo?(kats)
(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #38)
> There seems to be a big spike from Oct 16 - Oct 19, which doesn't seem to
> correspond to any activity on bug 1488871.

Yeah, emilio noted that it got backed out but the bug was never reopened
for some reason, so it can't be related that bug.
The regression range I'm getting [1] is not looking too useful. But I guess the larger problem here is that the test is trying to invoke APZ code without actually waiting to make sure APZ is ready. This would probably explain the slow trickle of intermittents going back more than a year as well. I can try to write a patch for this.

[1] https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=windows%2C10%2Cx64%2Cquantumrender%2Copt%2Cmochitests%2Cwith%2Ce10s%2Ctest-windows10-64-qr%2Fopt-mochitest-e10s-4%2Cm-e10s%284%29&tochange=f2e35ed6a6928b35e085462dc4268fd86f00fdb9&group_state=expanded&fromchange=ab9dfffff004480f216246435f2de37f801a636c
All the failures in that try push are for bug 1499996 so the patch seems good.
Assignee: nobody → kats
Flags: needinfo?(tnikkel)
(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #40)

> This would probably
> explain the slow trickle of intermittents going back more than a year as
> well. I can try to write a patch for this.

Kats: Thank you for making the time to investigate this, much appreciated.
Pushed by kgupta@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4e9062d05672
Wait until APZ is ready before sending it a wheel event. r=mats
https://hg.mozilla.org/mozilla-central/rev/4e9062d05672
Status: REOPENED → RESOLVED
Closed: 2 years agoLast year
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
https://hg.mozilla.org/releases/mozilla-beta/rev/162f30523a12
Flags: in-testsuite+
Whiteboard: [stockwell needswork] → [stockwell fixed]
You need to log in before you can comment on or make changes to this bug.