Closed Bug 1438752 Opened 2 years ago Closed Last year

Intermittent dom/events/test/test_bug946632.html | Test timed out.

Categories

(Core :: DOM: Events, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla62
Tracking Status
firefox62 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disable-recommended])

Attachments

(2 files)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Recent log failure: 
https://treeherder.mozilla.org/logviewer.html#?job_id=176195114&repo=mozilla-inbound&lineNumber=4596
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
There are 47 failures in the past 7 days.
Platforms: most of the occurrences are on windows10-64-qr, three times linux64-qr opt, and twice on linux64-qr debug.

Recent log failure: https://treeherder.mozilla.org/logviewer.html#?job_id=181255881&repo=autoland&lineNumber=1481

Relevant part of the log: 00:56:35     INFO -  205 INFO TEST-START | dom/events/test/test_bug946632.html
00:56:38     INFO -  GECKO(8960) | [Parent 8960, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
00:56:38     INFO -  GECKO(8960) | [Parent 8960, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
01:01:50     INFO -  TEST-INFO | started process screenshot
01:01:50     INFO -  TEST-INFO | screenshot: exit 0
01:01:50     INFO -  Buffered messages logged at 00:56:35
01:01:50     INFO -  206 INFO must wait for load
01:01:50     INFO -  Buffered messages logged at 00:56:36
01:01:50     INFO -  207 INFO TEST-PASS | dom/events/test/test_bug946632.html | <input> vertical line scroll targets container
01:01:50     INFO -  208 INFO TEST-PASS | dom/events/test/test_bug946632.html | <input> vertical line scroll container.scrollTop
01:01:50     INFO -  209 INFO TEST-PASS | dom/events/test/test_bug946632.html | <input> vertical line scroll container.scrollLeft
01:01:50     INFO -  210 INFO TEST-PASS | dom/events/test/test_bug946632.html | <input> horizontal line scroll input.scrollTop
01:01:50     INFO -  211 INFO TEST-PASS | dom/events/test/test_bug946632.html | <input> horizontal line scroll input.scrollLeft
01:01:50     INFO -  Buffered messages finished
01:01:50    ERROR -  212 INFO TEST-UNEXPECTED-FAIL | dom/events/test/test_bug946632.html | Test timed out.
01:01:50     INFO -      reportError@SimpleTest/TestRunner.js:121:7
01:01:50     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
01:01:50     INFO -      TestRunner.runTests@SimpleTest/TestRunner.js:380:5
01:01:50     INFO -      RunSet.runtests@SimpleTest/setup.js:194:3
01:01:50     INFO -      RunSet.runall@SimpleTest/setup.js:173:5
01:01:50     INFO -      hookupTests@SimpleTest/setup.js:266:5

:overholt Can you please take a look here?
Flags: needinfo?(overholt)
I can look at this on Monday. The failures seem to be QR-only.
Assignee: nobody → bugmail
Flags: needinfo?(overholt)
I tried reproducing this locally on both windows and linux, but was unable to. I'll do a try push with logging and see if I can chase it down.
That being said it's quite possible that https://github.com/servo/webrender/pull/2797 will fix this.
Comment on attachment 8983667 [details] [diff] [review]
Skipped test_bug946632.html on webrender for frequent failures

Review of attachment 8983667 [details] [diff] [review]:
-----------------------------------------------------------------

looks good
Attachment #8983667 - Flags: review?(jmaher) → review+
:kats, has the PR you submitted upstream made it into mozilla-central?  I am not able to easily find reference to that from github or your try push.
Flags: needinfo?(bugmail)
The patch is currently up for review in bug 1466549. I expect it to land today.
Flags: needinfo?(bugmail)
And it's on autoland now. I'd prefer to hold off on landing the patch here unless the failure shows up on a QR job which has bug 1466549 applied.
The volume is way down but it looks like it's still happening a little. I'll keep an eye on it.
So I think the problem here is a race condition in the test case. The test uses waitForAllPaintsFlushed [1] to flush stuff to the compositor, and then does a sendWheelAndPaint [2] to send a wheel input. The problem is waitForAllPaintsFlushed sends the updated display list over PCompositorBridge, and then continues. sendWheelAndPaint will send the wheel event to the parent process via PContent, which is a separate top-level protocol. So there's no ordering guarantee here, and the wheel event sent by sendWheelAndPaint can actually get processed by APZ before it has the updated hit-testing tree that comes with the display list. This can result in a hit-testing failure that can hang the test.

I was able to intermittently reproduce this by putting a sleep in the right spot after much trial and error, and I had sufficient logging that was consistent with this theory.

The fix here would be to make sure we don't proceed to the sendWheelAndPaint until we know that the APZ updater thread has built the hit-testing tree that goes with the display list. I think if we use one of the APZ flushing functions that should do the job here.

[1] https://searchfox.org/mozilla-central/rev/cf464eabfeba64e866c1fa36b9fefd674dca9c51/dom/events/test/test_bug946632.html#144
[2] https://searchfox.org/mozilla-central/rev/cf464eabfeba64e866c1fa36b9fefd674dca9c51/dom/events/test/test_bug946632.html#147
Comment on attachment 8984280 [details]
Summary: Wait for an APZ flush before scrolling to avoid race condition in test.

Ryan Hunt [:rhunt] has approved the revision.

https://phabricator.services.mozilla.com/D1585
Attachment #8984280 - Flags: review+
Pushed by kgupta@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/b79113fa763b
Summary: Wait for an APZ flush before scrolling to avoid race condition in test. r=rhunt
https://hg.mozilla.org/mozilla-central/rev/b79113fa763b
Status: REOPENED → RESOLVED
Closed: 2 years agoLast year
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
Looks fixed. If this comes back please file a new bug instead of reopening this one.
See Also: → 1479720
You need to log in before you can comment on or make changes to this bug.