Closed Bug 1374166 Opened 9 years ago Closed 8 years ago

Intermittent gfx/layers/apz/test/mochitest/test_bug1151663.html | found the RCD node

Categories

(Core :: Panning and Zooming, defect, P5)

Product:
Core
Component:
Panning and Zooming
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla60
Tracking Flags:
Tracking Status
firefox60 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [gfx-noted], [stockwell fixed:timing])

Attachments

(1 file)

Bug 1374166 - Use waitUntilApzStable to increase test robustness.
59 bytes, text/x-review-board-request
botond
: review+
Details
https://wiki.mozilla.org/Bugmasters#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Priority: -- → P5
Whiteboard: [gfx-noted]
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 9 years ago → 8 years ago
Resolution: --- → INCOMPLETE
This bug failed 37 times in the last 7 days only on Linux affecting opt build types. Failing tests: opt-mochitest-e10 Link to a recent log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=160757961 Part of that log: impleTest START [task 2018-02-07T03:29:09.518Z] 03:29:09 INFO - TEST-START | gfx/layers/apz/test/mochitest/test_bug1151663.html [task 2018-02-07T03:29:11.037Z] 03:29:11 INFO - TEST-INFO | started process screentopng [task 2018-02-07T03:29:11.537Z] 03:29:11 INFO - TEST-INFO | screentopng: exit 0 [task 2018-02-07T03:29:11.538Z] 03:29:11 INFO - Buffered messages logged at 03:29:11 [task 2018-02-07T03:29:11.539Z] 03:29:11 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_bug1151663.html | expected at least one paint in compositor test data [task 2018-02-07T03:29:11.540Z] 03:29:11 INFO - Buffered messages finished [task 2018-02-07T03:29:11.541Z] 03:29:11 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_bug1151663.html | found the RCD node [task 2018-02-07T03:29:11.542Z] 03:29:11 INFO - testBug1151663@gfx/layers/apz/test/mochitest/helper_bug1151663.html:67:7 [task 2018-02-07T03:29:11.543Z] 03:29:11 INFO - afterPaint@gfx/layers/apz/test/mochitest/helper_bug1151663.html:30:7 [task 2018-02-07T03:29:11.544Z] 03:29:11 INFO - EventListener.handleEvent*window.onload@gfx/layers/apz/test/mochitest/helper_bug1151663.html:18:9 [task 2018-02-07T03:29:11.545Z] 03:29:11 INFO - EventHandlerNonNull*@gfx/layers/apz/test/mochitest/helper_bug1151663.html:17:5 [task 2018-02-07T03:29:11.546Z] 03:29:11 INFO - GECKO(5327) | JavaScript error: http://mochi.test:8888/tests/gfx/layers/apz/test/mochitest/helper_bug1151663.html, line 68: TypeError: rcd is null [task 2018-02-07T03:34:09.520Z] 03:34:09 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-07T03:34:09.522Z] 03:34:09 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_bug1151663.html | Test timed out. [task 2018-02-07T03:34:09.522Z] 03:34:09 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-07T03:34:09.522Z] 03:34:09 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 :kats could you please take a look?
Flags: needinfo?(bugmail)
Whiteboard: [gfx-noted] → [gfx-noted], [stockwell needswork]
Assignee: nobody → bugmail
Flags: needinfo?(bugmail)
Quick update: I can reproduce this locally if I run the APZ mochitests with --repeat 1. On the second time around the test_bug1151663.html fails in exactly the same way. I'm trying to debug what's going on but it's complicated and will take a couple of days.
I spent more time today digging into this. At the point where the helper page tries to get the compositor APZ data, the compositor's layer tree has the chrome's refLayer pointing to the old content. That is, initially we have this: Chrome layer tree (layers id = 0x10000001) -> Ref layer (remote layers id = 0x10000002) Content layer tree (layers id = 0x10000002) Then the new tab opens with helper_bug1151663.html page and we have this: Chrome layer tree (layers id = 0x10000001) -> Ref layer (remote layers id = 0x10000002) // this is still pointing to the old page Content layer tree (layers id = 0x10000002) Content layer tree (layers id = 0x1000000e) // this is the helper_bug1151663.html page The new content layer manager does paint itself, sends a display list to the compositor, and clears the MozAfterPaint state, but that means nothing because the chrome layer tree is still pointing to the wrong thing. It's only after the parent-process layer tree updates that we can successfully query the APZ test data for what we want. It seems like this happens intermittently even without WR, but it happens much more frequently with WR because there's a backlog of render events on layers id 0x10000002 that seem to slow things down, and delays the DidComposite notification that triggers the parent process to hook up the new layer tree. I think the backlog of render events might be a separate issue that will show up in other tests as well, but we can fix the immediate problem by making this test more robust and not spawning the helper page until the backlog is cleared.
Comment on attachment 8949521 [details] Bug 1374166 - Use waitUntilApzStable to increase test robustness. https://reviewboard.mozilla.org/r/218876/#review224856 Thanks for looking into and fixing this! ::: commit-message-c5120:6 (Diff revision 1) > +Bug 1374166 - Use waitUntilApzStable to increase test robustness. r?botond > + > +The important part here is that the test parent page > +(test_bug1151663.html) waits for paints to complete before spawning the > +helper window. Otherwise, the helper window might think it's done > +painting (because it is) and start running the test even though it's s/it's/its ::: commit-message-c5120:11 (Diff revision 1) > +painting (because it is) and start running the test even though it's > +layer tree has not been attached to the chrome layer tree. In such a > +scenario reading the APZ test data produces an empty tree for the > +content layers id and causes the test to fail. > + > +This test was written before we had waitUntilApzStable so sprinking some s/sprinking/sprinkling ::: gfx/layers/apz/test/mochitest/helper_bug1151663.html:10 (Diff revision 1) > --> > <head> > <meta charset="utf-8"> > <title>Test for Bug 1151663, helper page</title> > <script type="application/javascript" src="apz_test_utils.js"></script> > + <script type="application/javascript" src="/tests/SimpleTest/paint_listener.js"></script> It may be worth adding a comment at the top of apz_test_utils.js (where in a grown-up language there might be an include/import) that says "if you use waitForApzFlushedRepaints or waitUntilApzStable from this file, your HTML file needs to include SimpleTest/paint_listener.js as well".
Attachment #8949521 - Flags: review?(botond) → review+
(In reply to Botond Ballo [:botond] from comment #27) > s/it's/its Fixed > ::: commit-message-c5120:11 > s/sprinking/sprinkling Fixed > ::: gfx/layers/apz/test/mochitest/helper_bug1151663.html:10 > It may be worth adding a comment at the top of apz_test_utils.js (where in a > grown-up language there might be an include/import) that says "if you use > waitForApzFlushedRepaints or waitUntilApzStable from this file, your HTML > file needs to include SimpleTest/paint_listener.js as well". I don't know if it's worth it - I would never go look at the top of apz_test_utils.js when I include it into a .html file. And the Javascript error that's produced when you miss the include is pretty easy to decipher (unlike many other kinds of JS errors).
Pushed by kgupta@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/63ff291a2433 Use waitUntilApzStable to increase test robustness. r=botond
https://hg.mozilla.org/mozilla-central/rev/63ff291a2433
Status: REOPENED → RESOLVED
Closed: 8 years ago → 8 years ago
status-firefox60: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla60
Recent failure log (tier2 so far): https://treeherder.mozilla.org/logviewer.html#?job_id=161499090&repo=autoland&lineNumber=6713 [task 2018-02-10T10:55:35.248Z] 10:55:35 INFO - TEST-START | gfx/layers/apz/test/mochitest/test_bug1151663.html [task 2018-02-10T10:55:36.478Z] 10:55:36 INFO - GECKO(5455) | Flushed APZ repaints, waiting for callback... [task 2018-02-10T10:55:36.825Z] 10:55:36 INFO - GECKO(5455) | Flushed APZ repaints, waiting for callback... [task 2018-02-10T10:55:36.848Z] 10:55:36 INFO - TEST-INFO | started process screentopng [task 2018-02-10T10:55:37.450Z] 10:55:37 INFO - TEST-INFO | screentopng: exit 0 [task 2018-02-10T10:55:37.451Z] 10:55:37 INFO - Buffered messages logged at 10:55:36 [task 2018-02-10T10:55:37.452Z] 10:55:37 INFO - must wait for load [task 2018-02-10T10:55:37.453Z] 10:55:37 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_bug1151663.html | expected at least one paint in compositor test data [task 2018-02-10T10:55:37.453Z] 10:55:37 INFO - Buffered messages finished [task 2018-02-10T10:55:37.454Z] 10:55:37 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_bug1151663.html | found the RCD node [task 2018-02-10T10:55:37.454Z] 10:55:37 INFO - testBug1151663@gfx/layers/apz/test/mochitest/helper_bug1151663.html:53:7 [task 2018-02-10T10:55:37.455Z] 10:55:37 INFO - promise callback*@gfx/layers/apz/test/mochitest/helper_bug1151663.html:59:5 [task 2018-02-10T10:55:37.456Z] 10:55:37 INFO - GECKO(5455) | JavaScript error: http://mochi.test:8888/tests/gfx/layers/apz/test/mochitest/helper_bug1151663.html, line 54: TypeError: rcd is null [task 2018-02-10T11:00:35.254Z] 11:00:35 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-10T11:00:35.256Z] 11:00:35 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_bug1151663.html | Test timed out. [task 2018-02-10T11:00:35.256Z] 11:00:35 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-10T11:00:35.257Z] 11:00:35 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 [task 2018-02-10T11:00:35.257Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.258Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.259Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.259Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.260Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.260Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.261Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.262Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.262Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.262Z] 11:00:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:00:35.263Z] 11:00:35 INFO - TestRunner.runTests@SimpleTest/TestRunner.js:380:5 [task 2018-02-10T11:00:35.264Z] 11:00:35 INFO - RunSet.runtests@SimpleTest/setup.js:194:3 [task 2018-02-10T11:00:35.264Z] 11:00:35 INFO - RunSet.runall@SimpleTest/setup.js:173:5 [task 2018-02-10T11:00:35.265Z] 11:00:35 INFO - hookupTests@SimpleTest/setup.js:266:5 [task 2018-02-10T11:00:35.265Z] 11:00:35 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5 [task 2018-02-10T11:00:35.266Z] 11:00:35 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11 [task 2018-02-10T11:00:35.266Z] 11:00:35 INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3 [task 2018-02-10T11:00:35.267Z] 11:00:35 INFO - hookup@SimpleTest/setup.js:246:5 [task 2018-02-10T11:00:35.268Z] 11:00:35 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1 [task 2018-02-10T11:00:36.263Z] 11:00:36 INFO - GECKO(5455) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration. [task 2018-02-10T11:00:36.264Z] 11:00:36 INFO - GECKO(5455) | MEMORY STAT | vsize 1592MB | residentFast 128MB | heapAllocated 24MB [task 2018-02-10T11:00:39.270Z] 11:00:39 INFO - TEST-OK | gfx/layers/apz/test/mochitest/test_bug1151663.html | took 304021ms [task 2018-02-10T11:00:42.281Z] 11:00:42 INFO - Error: Unable to restore focus, expect failures and timeouts. [task 2018-02-10T11:00:42.309Z] 11:00:42 INFO - TEST-START | gfx/layers/apz/test/mochitest/test_bug1151667.html [task 2018-02-10T11:06:05.263Z] 11:06:05 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-10T11:06:05.265Z] 11:06:05 INFO - Buffered messages logged at 11:00:46 [task 2018-02-10T11:06:05.266Z] 11:06:05 INFO - Error: Unable to restore focus, expect failures and timeouts. [task 2018-02-10T11:06:05.267Z] 11:06:05 INFO - must wait for load [task 2018-02-10T11:06:05.268Z] 11:06:05 INFO - must wait for focus [task 2018-02-10T11:06:05.268Z] 11:06:05 INFO - Buffered messages finished [task 2018-02-10T11:06:05.269Z] 11:06:05 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_bug1151667.html | Test timed out. [task 2018-02-10T11:06:05.269Z] 11:06:05 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-10T11:06:05.269Z] 11:06:05 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 [task 2018-02-10T11:06:05.270Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.270Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.271Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.271Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.271Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.272Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.272Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.272Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.273Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.273Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.273Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.274Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.274Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.275Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.275Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.276Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.276Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.277Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.277Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.277Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.278Z] 11:06:05 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:05.278Z] 11:06:05 INFO - TestRunner.runTests@SimpleTest/TestRunner.js:380:5 [task 2018-02-10T11:06:05.278Z] 11:06:05 INFO - RunSet.runtests@SimpleTest/setup.js:194:3 [task 2018-02-10T11:06:05.279Z] 11:06:05 INFO - RunSet.runall@SimpleTest/setup.js:173:5 [task 2018-02-10T11:06:05.279Z] 11:06:05 INFO - hookupTests@SimpleTest/setup.js:266:5 [task 2018-02-10T11:06:05.280Z] 11:06:05 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5 [task 2018-02-10T11:06:05.280Z] 11:06:05 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11 [task 2018-02-10T11:06:05.280Z] 11:06:05 INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3 [task 2018-02-10T11:06:05.281Z] 11:06:05 INFO - hookup@SimpleTest/setup.js:246:5 [task 2018-02-10T11:06:05.281Z] 11:06:05 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1 [task 2018-02-10T11:06:06.272Z] 11:06:06 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-10T11:06:06.273Z] 11:06:06 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_bug1151667.html | [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run. Maybe the test terminated prematurely -- be sure to use SimpleTest.waitForExplicitFinish(). - got 1, expected +0 [task 2018-02-10T11:06:06.274Z] 11:06:06 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:312:5 [task 2018-02-10T11:06:06.275Z] 11:06:06 INFO - afterCleanup@SimpleTest/SimpleTest.js:1169:13 [task 2018-02-10T11:06:06.275Z] 11:06:06 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1211:13 [task 2018-02-10T11:06:06.275Z] 11:06:06 INFO - SimpleTest.finish@SimpleTest/SimpleTest.js:1230:5 [task 2018-02-10T11:06:06.276Z] 11:06:06 INFO - killTest@SimpleTest/TestRunner.js:130:7 [task 2018-02-10T11:06:06.277Z] 11:06:06 INFO - delayedKillTest@SimpleTest/TestRunner.js:157:47 [task 2018-02-10T11:06:06.277Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:157:7 [task 2018-02-10T11:06:06.277Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.278Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.279Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.279Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.280Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.280Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.281Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.282Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.282Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.283Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.283Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.284Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.284Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.285Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.285Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.286Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.286Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.287Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.287Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.288Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.288Z] 11:06:06 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:06:06.289Z] 11:06:06 INFO - TestRunner.runTests@SimpleTest/TestRunner.js:380:5 [task 2018-02-10T11:06:06.289Z] 11:06:06 INFO - RunSet.runtests@SimpleTest/setup.js:194:3 [task 2018-02-10T11:06:06.290Z] 11:06:06 INFO - RunSet.runall@SimpleTest/setup.js:173:5 [task 2018-02-10T11:06:06.291Z] 11:06:06 INFO - hookupTests@SimpleTest/setup.js:266:5 [task 2018-02-10T11:06:06.291Z] 11:06:06 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5 [task 2018-02-10T11:06:06.292Z] 11:06:06 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11 [task 2018-02-10T11:06:06.292Z] 11:06:06 INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3 [task 2018-02-10T11:06:06.292Z] 11:06:06 INFO - hookup@SimpleTest/setup.js:246:5 [task 2018-02-10T11:06:06.293Z] 11:06:06 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1 [task 2018-02-10T11:06:06.294Z] 11:06:06 INFO - GECKO(5455) | MEMORY STAT | vsize 1592MB | residentFast 129MB | heapAllocated 25MB [task 2018-02-10T11:06:08.271Z] 11:06:08 INFO - TEST-OK | gfx/layers/apz/test/mochitest/test_bug1151667.html | took 325963ms [task 2018-02-10T11:06:11.277Z] 11:06:11 INFO - Error: Unable to restore focus, expect failures and timeouts. [task 2018-02-10T11:06:11.292Z] 11:06:11 ERROR - /tests/gfx/layers/apz/test/mochitest/test_bug1151667.html logged result after SimpleTest.finish(): [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run. Maybe the test terminated prematurely -- be sure to use SimpleTest.waitForExplicitFinish(). [task 2018-02-10T11:06:11.308Z] 11:06:11 INFO - TEST-START | gfx/layers/apz/test/mochitest/test_bug1253683.html [task 2018-02-10T11:11:35.275Z] 11:11:35 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-10T11:11:35.276Z] 11:11:35 INFO - Buffered messages logged at 11:06:15 [task 2018-02-10T11:11:35.277Z] 11:11:35 INFO - Error: Unable to restore focus, expect failures and timeouts. [task 2018-02-10T11:11:35.278Z] 11:11:35 INFO - Buffered messages logged at 11:06:17 [task 2018-02-10T11:11:35.278Z] 11:11:35 INFO - must wait for focus [task 2018-02-10T11:11:35.278Z] 11:11:35 INFO - Buffered messages finished [task 2018-02-10T11:11:35.279Z] 11:11:35 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_bug1253683.html | Test timed out. [task 2018-02-10T11:11:35.279Z] 11:11:35 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-10T11:11:35.280Z] 11:11:35 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 [task 2018-02-10T11:11:35.280Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.280Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.281Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.281Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.282Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.282Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.283Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.283Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.284Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.284Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.284Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.285Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.285Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.286Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.286Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.286Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.287Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.288Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.288Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.288Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.289Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.289Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.289Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.289Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.290Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.290Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.291Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.291Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.292Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.292Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.292Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.292Z] 11:11:35 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5 [task 2018-02-10T11:11:35.293Z] 11:11:35 INFO - TestRunner.runTests@SimpleTest/TestRunner.js:380:5 [task 2018-02-10T11:11:35.294Z] 11:11:35 INFO - RunSet.runtests@SimpleTest/setup.js:194:3 [task 2018-02-10T11:11:35.294Z] 11:11:35 INFO - RunSet.runall@SimpleTest/setup.js:173:5 [task 2018-02-10T11:11:35.294Z] 11:11:35 INFO - hookupTests@SimpleTest/setup.js:266:5 [task 2018-02-10T11:11:35.295Z] 11:11:35 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5 [task 2018-02-10T11:11:35.295Z] 11:11:35 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11 [task 2018-02-10T11:11:35.295Z] 11:11:35 INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3 [task 2018-02-10T11:11:35.295Z] 11:11:35 INFO - hookup@SimpleTest/setup.js:246:5 [task 2018-02-10T11:11:35.295Z] 11:11:35 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1 [task 2018-02-10T11:11:36.283Z] 11:11:36 INFO - Not taking screenshot here: see the one that was previously logged
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
https://hg.mozilla.org/mozilla-central/rev/63ff291a2433
Status: REOPENED → RESOLVED
Closed: 8 years ago → 8 years ago
Resolution: --- → FIXED
(In reply to Andreea Pavel [:apavel] from comment #32) > Recent failure log (tier2 so far): > https://treeherder.mozilla.org/logviewer. > html#?job_id=161499090&repo=autoland&lineNumber=6713 Hm, this one might be specific to QuantumRender. I've cloned this bug to bug 1437295, we can use that to track the issue.
:kats thank you.
Whiteboard: [gfx-noted], [stockwell needswork] → [gfx-noted], [stockwell fixed:timing]
Blocks: 1452800
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: