Closed Bug 1174323 Opened 5 years ago Closed 4 years ago

Intermittent test_pointerlock-api.html | file_screenClientXYConst.html: clientX should be equal to where the mouse was originaly locked - got 800, expected 270

Categories

(Core :: DOM: Core & HTML, defect)

41 Branch
Unspecified
macOS
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla46
Tracking Status
firefox40 --- unaffected
firefox41 --- disabled
firefox42 --- disabled
firefox46 --- fixed
firefox-esr31 --- unaffected
firefox-esr38 --- unaffected

People

(Reporter: KWierso, Assigned: xidorn)

References

Details

(Keywords: intermittent-failure)

Attachments

(4 files, 1 obsolete file)

14:14:07 INFO - 203 INFO TEST-START | dom/tests/mochitest/pointerlock/test_pointerlock-api.html
14:14:08 INFO - [POINTERLOCK] Starting file_approval.html
14:14:08 INFO - [POINTERLOCK] Finishing file_approval.html
14:14:09 INFO - [POINTERLOCK] Starting file_screenClientXYConst.html
14:14:09 INFO - 204 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_approval.html: Should only receive mozpointerlockchange when we've been approved for fullscreen.
14:14:09 INFO - 205 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_approval.html: Should only receive mozpointerlockchange when we've been approved for fullscreen.
14:14:09 INFO - 206 INFO must wait for focus
14:14:09 INFO - 207 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_screenClientXYConst.html: Pointer should be unlocked
14:14:09 INFO - 208 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_screenClientXYConst.html: Pointer should be locked
14:14:09 INFO - 209 INFO TEST-UNEXPECTED-FAIL | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_screenClientXYConst.html: clientX should be equal to where the mouse was originaly locked - got 800, expected 270
14:14:09 INFO - 210 INFO TEST-UNEXPECTED-FAIL | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_screenClientXYConst.html: clientY should be equal to where the mouse was originaly locked - got 600, expected 71
14:14:09 INFO - 211 INFO TEST-UNEXPECTED-FAIL | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_screenClientXYConst.html: screenX should be equal to where the mouse was originaly locked - got 800, expected 287
14:14:09 INFO - 212 INFO TEST-UNEXPECTED-FAIL | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_screenClientXYConst.html: screenY should be equal to where the mouse was originaly locked - got 600, expected 431
14:14:09 INFO - [POINTERLOCK] Finishing file_screenClientXYConst.html
14:14:09 INFO - 213 INFO must wait for focus
14:14:10 INFO - [POINTERLOCK] Starting file_childIframe.html
14:14:10 INFO - 214 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_childIframe.html: Pointer should be locked even when pointer hovers over a child iframe
14:14:10 INFO - 215 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_childIframe.html: MovementX of first move to childDiv should be equal to movementX of second move to child div
14:14:10 INFO - 216 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_childIframe.html: MovementY of first move to childDiv should be equal to movementY of second move to child div
14:14:10 INFO - [POINTERLOCK] Finishing file_childIframe.html
14:14:10 INFO - 217 INFO must wait for focus
14:14:11 INFO - [POINTERLOCK] Starting file_doubleLock.html
14:14:12 INFO - 218 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_doubleLock.html: Requesting pointer lock on a locked element should dispatch mozpointerlockchange event
14:14:12 INFO - [POINTERLOCK] Finishing file_doubleLock.html
14:14:12 INFO - 219 INFO must wait for focus
14:14:12 INFO - [POINTERLOCK] Starting file_escapeKey.html
14:14:13 INFO - 220 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_escapeKey.html: Pressing Escape key should unlock the pointer
14:14:13 INFO - [POINTERLOCK] Finishing file_escapeKey.html
14:14:13 INFO - 221 INFO must wait for focus
14:14:13 INFO - [POINTERLOCK] Starting file_infiniteMovement.html
14:14:14 INFO - 222 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_infiniteMovement.html: Should have moved more than one screen's worth in width.TotalX: 2000 Screensize X: 484
14:14:14 INFO - 223 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_infiniteMovement.html: Should have moved more than one screen's worth in height.TotalY: 1500 Screensize Y: 0
14:14:14 INFO - [POINTERLOCK] Finishing file_infiniteMovement.html
14:14:14 INFO - 224 INFO must wait for focus
14:14:14 INFO - [POINTERLOCK] Starting file_locksvgelement.html
14:14:15 INFO - 225 INFO TEST-PASS | dom/tests/mochitest/pointerlock/test_pointerlock-api.html | file_locksvgelement.html: Expected SVG elem to become locked.
14:14:15 INFO - [POINTERLOCK] Finishing file_locksvgelement.html
14:14:15 INFO - 226 INFO must wait for focus
(In reply to Wes Kocher (:KWierso) from comment #5)
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&filter-
> searchStr=OS%20X%2010.
> 6%20opt%20Mochitest%20Mochitest%20M%284%29&fromchange=bfd82015df48 makes it
> look like this merged to m-c from inbound in
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-
> central&revision=203e1025a826
> 
> 
> Backfilling results on inbound in
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-
> searchStr=OS%20X%2010.
> 6%20opt%20Mochitest%20Mochitest%20M%284%29&fromchange=6231a72d0557&tochange=3
> 03ced6f21b9

First instance I see this in is when bug 1168028 landed. Retriggering more on prior pushes to confirm, though.
Depends on: 1168028
I saw this in my try push for bug 1168705, but didn't realize that it is because of bug 1168028.

For this intermittent I have one possible workaround: https://hg.mozilla.org/try/rev/29f35cd7d3b4 (try push https://treeherder.mozilla.org/#/jobs?repo=try&revision=29f35cd7d3b4 ), but I don't have idea how that works.
Hmm, it seems that isn't a successful workaround.
It seems my patches for bug 1168705 would make this intermittent be triggered reliably: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c11bf50deefa . It's probably a good start point for me to investigate.
I cannot reproduce this failure on either my Mac OS X 10.9 or my Windows. So I pushed a try build with some diagnose code: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a2da11a868a2

It seems there is an unexpected real mouse event appears between the synthesized mousemove event and pointerlock finishes, which affects the last position we record:

This is our synthesized mousemove event:
19:45:44     INFO -  !!!!!!! record screen point: 800,600
19:45:44     INFO -  #01: PresShell::HandlePositionedEvent(nsIFrame*, mozilla::WidgetGUIEvent*, nsEventStatus*) [layout/base/nsPresShell.cpp:8016]
19:45:44     INFO -  #02: PresShell::HandleEvent(nsIFrame*, mozilla::WidgetGUIEvent*, bool, nsEventStatus*, nsIContent**) [layout/base/nsPresShell.cpp:7803]
19:45:44     INFO -  #03: nsViewManager::DispatchEvent(mozilla::WidgetGUIEvent*, nsView*, nsEventStatus*) [xpcom/glue/nsCOMPtr.h:389]
19:45:44     INFO -  #04: nsView::HandleEvent(mozilla::WidgetGUIEvent*, bool) [xpcom/base/nsRefPtr.h:66]
19:45:44     INFO -  #05: nsChildView::DispatchEvent(mozilla::WidgetGUIEvent*, nsEventStatus&) [widget/cocoa/nsChildView.mm:1450]
19:45:44     INFO -  #06: nsContentUtils::SendMouseEvent(nsCOMPtr<nsIPresShell>, nsAString_internal const&, float, float, int, int, int, bool, float, unsigned short, bool, bool*, bool) [dom/base/nsContentUtils.cpp:7745]
19:45:44     INFO -  #07: nsDOMWindowUtils::SendMouseEventCommon(nsAString_internal const&, float, float, int, int, int, bool, float, unsigned short, bool, bool*, bool) [dom/base/nsDOMWindowUtils.cpp:664]
19:45:44     INFO -  #08: nsDOMWindowUtils::SendMouseEvent(nsAString_internal const&, float, float, int, int, int, bool, float, unsigned short, bool, unsigned char, bool*) [dom/base/nsDOMWindowUtils.cpp:619]

This is the following real mouse event:
19:45:44     INFO -  !!!!!!! record screen point: 287,431
19:45:44     INFO -  #01: PresShell::HandlePositionedEvent(nsIFrame*, mozilla::WidgetGUIEvent*, nsEventStatus*) [layout/base/nsPresShell.cpp:8016]
19:45:44     INFO -  #02: PresShell::HandleEvent(nsIFrame*, mozilla::WidgetGUIEvent*, bool, nsEventStatus*, nsIContent**) [layout/base/nsPresShell.cpp:7803]
19:45:44     INFO -  #03: nsViewManager::DispatchEvent(mozilla::WidgetGUIEvent*, nsView*, nsEventStatus*) [xpcom/glue/nsCOMPtr.h:389]
19:45:44     INFO -  #04: nsView::HandleEvent(mozilla::WidgetGUIEvent*, bool) [xpcom/base/nsRefPtr.h:66]
19:45:44     INFO -  #05: nsChildView::DispatchEvent(mozilla::WidgetGUIEvent*, nsEventStatus&) [widget/cocoa/nsChildView.mm:1450]
19:45:44     INFO -  #06: nsBaseWidget::DispatchInputEvent(mozilla::WidgetInputEvent*) [widget/nsBaseWidget.cpp:1080]
19:45:44     INFO -  #07: -[ChildView inactiveWindowAcceptsMouseEvent:] [widget/cocoa/nsChildView.mm:5510]
19:45:44     INFO -  #08: ChildViewMouseTracker::WindowAcceptsEvent(NSWindow*, NSEvent*, ChildView*, signed char) [widget/cocoa/nsChildView.mm:6381]
19:45:44     INFO -  #09: ChildViewMouseTracker::ViewForEvent(NSEvent*) [widget/cocoa/nsChildView.mm:6322]
19:45:44     INFO -  #10: ChildViewMouseTracker::MouseEnteredWindow(NSEvent*) [widget/cocoa/nsChildView.mm:6262]

It seems that the second event is from an inactive window. Not sure how that happens, given that the testing window should have been in fullscreen and covered all other windows.
As bug 1168705 turns this intermittent to a permafail, mark it as a blocker of that bug.
Blocks: 1168705, 1168028
No longer depends on: 1168028
Great. I upgraded my system to OS X 10.10. Now I can reliably reproduce this intermittent failure.
Attached patch patch (obsolete) — Splinter Review
try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=da6e99befd77

The intermittent failure in this try push is another problem, which is timeout of the next test file_childIframe, which is one of the reasons we cannot enable the pointerlock tests on other platforms.
Attachment #8622401 - Flags: review?(wkocher)
Attached patch patchSplinter Review
Attachment #8622401 - Attachment is obsolete: true
Attachment #8622401 - Flags: review?(wkocher)
Attachment #8622403 - Flags: review?(wkocher)
It seems that this patch would potentially increase the chance of the timeout on file_childIframe. Need to figure out what happens there. But that should be in another bug. Probably bug 788164 or bug 931445.
I'm in no position to actually review this, but I'm happy to rubberstamp it if you think this'll work.
Attachment #8622403 - Flags: review?(wkocher) → review+
My patch may not completely fix this intermittent, as I cannot figure out any approach to prevent the system to insert a random mouse event between calling requestPointerLock and actually locks the pointer. And I also don't understand why there isn't such intermittent failure before bug 1168028.
Keywords: leave-open
I'll try to enable the tests on OS X 10.10 first (in bug 1170369), and then see if it makes sense to disable the specific subtest on 10.6.
(In reply to Xidorn Quan [:xidorn] (UTC+12) from comment #187)
> I'll try to enable the tests on OS X 10.10 first (in bug 1170369), and then
> see if it makes sense to disable the specific subtest on 10.6.

It seems 10.10 has the same issue here... Let's disable it on all Mac platforms...
Blocks: 1170369
Comment on attachment 8630904 [details] [diff] [review]
patch to disable the specific subtest

Happy to rubberstamp this.
Attachment #8630904 - Flags: review?(wkocher) → review+
I caught a failure in this test (although with different numbers) in rr today.
Let me know if you're interested in debugging it.
Flags: needinfo?(quanxunzhen)
Hmmm, this is a OSX-only intermittent on the test infra. I don't think recording in rr helps solving this. (Does rr now work on OS X?)

I had investigated this before. See comment 98. The reason of this intermittent is that, the system may occasionally insert a non-mousemove mouse event between we trigger the fake mouse move via synthesizeMouse() and the asynchronous pointer lock request finishes. When that happens, we record the mouse position in the last system event, instead of the one we specify in the synthesizeMouse() call, as the locked position. This is actually a race between our fake event and the system event.

I can imagine how you can reproduce this on Linux with rr: just need an accidental mouse event. I don't think that helps fixing this intermittent.
Flags: needinfo?(quanxunzhen)
[Mass Closure] Closing Intermittent as a one off
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → WORKSFORME
It is not resolved. It is disabled.
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Keywords: leave-open
So the basic idea of fixing this intermittent is that, we move the pointer position in the OS, instead of just simulating it inside our event system, so that even if the system sends unexpected mouse event to us, the position doesn't change.
Comment on attachment 8706729 [details]
MozReview Request: Bug 1174323 part 1 - Add nsDOMWindowUtils::SendNativeMouseMove and EventUtils.sendNativeMouseMove.

https://reviewboard.mozilla.org/r/30477/#review27347

I think that fixed, fine. So the function would return true or false, and call callback param
when observer's observe is called.

::: testing/mochitest/tests/SimpleTest/EventUtils.js:565
(Diff revision 1)
> +  return new Promise(resolve => {

EventUtils doesn't use Promises anywhere else, so rather odd to see them being used here.
Make the code look more like synthesizeNativeKey
Attachment #8706729 - Flags: review?(bugs) → review+
Comment on attachment 8706730 [details]
MozReview Request: Bug 1174323 part 2 - Use native mouse move to improve robustness of screenClientXYConst subtest.

https://reviewboard.mozilla.org/r/30479/#review27349

::: dom/tests/mochitest/pointerlock/file_screenClientXYConst.html:122
(Diff revision 1)
> +        synthesizeNativeMouseMove(div, 0, 0).then(() => {

and the previous patch changed, this would become 
synthesizeNativeMouseMove(div, 0, 0, function() {
  div.mozRequestFullScreen();
});
Attachment #8706730 - Flags: review?(bugs) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/43a7901e4fa1f7454017ee19c4b161eb8185e715
Bug 1174323 part 1 - Add nsDOMWindowUtils::SendNativeMouseMove and EventUtils.sendNativeMouseMove. r=smaug

https://hg.mozilla.org/integration/mozilla-inbound/rev/42a30788be42f53de84bfd0efb23086148261f30
Bug 1174323 part 2 - Use native mouse move to improve robustness of screenClientXYConst subtest. r=smaug
Assignee: nobody → quanxunzhen
https://hg.mozilla.org/mozilla-central/rev/43a7901e4fa1
https://hg.mozilla.org/mozilla-central/rev/42a30788be42
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla46
You need to log in before you can comment on or make changes to this bug.