Closed Bug 1569512 Opened 6 years ago Closed 5 years ago

Intermittent dom/events/test/test_bug656379-2.html | Button 2 should be hovered after mousemove over button2 / label2 - got false, expected true

Categories

(Core :: DOM: Events, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla76
Tracking Status
firefox-esr68 --- unaffected
firefox73 --- wontfix
firefox74 --- wontfix
firefox75 --- wontfix
firefox76 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [test isolation])

Attachments

(1 file)

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=258718389&repo=mozilla-inbound
Full log: https://queue.taskcluster.net/v1/task/CbCWapwURd-9v-E-lK_S6g/runs/0/artifacts/public/logs/live_backing.log


[task 2019-07-29T00:14:40.332Z] 00:14:40 INFO - TEST-START | dom/events/test/test_bug656379-2.html
[task 2019-07-29T00:14:40.442Z] 00:14:40 INFO - TEST-INFO | started process screentopng
[task 2019-07-29T00:14:41.248Z] 00:14:41 INFO - TEST-INFO | screentopng: exit 0
[task 2019-07-29T00:14:41.249Z] 00:14:41 INFO - Buffered messages logged at 00:14:40
[task 2019-07-29T00:14:41.251Z] 00:14:41 INFO - must wait for load
[task 2019-07-29T00:14:41.252Z] 00:14:41 INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 1 should be hovered after mousemove over label1
[task 2019-07-29T00:14:41.252Z] 00:14:41 INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 1 should be hovered after mousemove over label1
[task 2019-07-29T00:14:41.253Z] 00:14:41 INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 2 should not be hovered after mousemove over label1
[task 2019-07-29T00:14:41.253Z] 00:14:41 INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 2 should not be hovered after mousemove over label1
[task 2019-07-29T00:14:41.254Z] 00:14:41 INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 1 should not be hovered after mousemove over button2
[task 2019-07-29T00:14:41.254Z] 00:14:41 INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 1 should not be hovered after mousemove over button2
[task 2019-07-29T00:14:41.254Z] 00:14:41 INFO - Buffered messages finished
[task 2019-07-29T00:14:41.255Z] 00:14:41 INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_bug656379-2.html | Button 2 should be hovered after mousemove over button2 - got false, expected true

Whiteboard: [test isolation]
Summary: Intermittent dom/events/test/test_bug656379-2.html | Button 2 should be hovered after mousemove over button2 - got false, expected true → Intermittent dom/events/test/test_bug656379-2.html | Button 2 should be hovered after mousemove over button2 / label2 - got false, expected true

Looks like that this bug and bug 1545222 are caused by same bug. Both of them occur only on opt and especially on shippable build. So, I guess that it's caused by some race condition.

I got log of mousemove for this bug

[task 2020-03-01T12:04:39.717Z] 12:04:39     INFO - TEST-START | dom/events/test/test_bug656379-2.html
[task 2020-03-01T12:04:39.793Z] 12:04:39     INFO - TEST-INFO | started process screentopng
[task 2020-03-01T12:04:40.114Z] 12:04:40     INFO - TEST-INFO | screentopng: exit 0
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - Buffered messages logged at 12:04:39
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - must wait for load
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - mouseover on P#display > LABEL#label1
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - mouseenter on HTML
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - mouseenter on HTML > BODY
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - mouseenter on P#display
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - mouseenter on P#display > LABEL#label1
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - Synthesizing mousemove on label1...
[task 2020-03-01T12:04:40.115Z] 12:04:40     INFO - mousemove on P#display > LABEL#label1
[task 2020-03-01T12:04:40.116Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 1 should be hovered after mousemove over label1 
[task 2020-03-01T12:04:40.116Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 1 should be hovered after mousemove over label1 
[task 2020-03-01T12:04:40.116Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 2 should not be hovered after mousemove over label1 
[task 2020-03-01T12:04:40.116Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 2 should not be hovered after mousemove over label1 
[task 2020-03-01T12:04:40.117Z] 12:04:40     INFO - Synthesizing mousemove on button2...
[task 2020-03-01T12:04:40.117Z] 12:04:40     INFO - mouseout on P#display > LABEL#label1
[task 2020-03-01T12:04:40.117Z] 12:04:40     INFO - mouseleave on P#display > LABEL#label1
[task 2020-03-01T12:04:40.117Z] 12:04:40     INFO - mouseover on P#display > LABEL > INPUT#button2
[task 2020-03-01T12:04:40.118Z] 12:04:40     INFO - mouseenter on P#display > LABEL
[task 2020-03-01T12:04:40.119Z] 12:04:40     INFO - mouseenter on P#display > LABEL > INPUT#button2
[task 2020-03-01T12:04:40.119Z] 12:04:40     INFO - mousemove on P#display > LABEL > INPUT#button2
[task 2020-03-01T12:04:40.120Z] 12:04:40     INFO - mouseout on P#display > LABEL > INPUT#button2
[task 2020-03-01T12:04:40.120Z] 12:04:40     INFO - mouseleave on P#display > LABEL > INPUT#button2
[task 2020-03-01T12:04:40.120Z] 12:04:40     INFO - mouseleave on P#display > LABEL
[task 2020-03-01T12:04:40.122Z] 12:04:40     INFO - mouseleave on P#display
[task 2020-03-01T12:04:40.123Z] 12:04:40     INFO - mouseover on HTML > BODY
[task 2020-03-01T12:04:40.123Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 1 should not be hovered after mousemove over button2 
[task 2020-03-01T12:04:40.124Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 1 should not be hovered after mousemove over button2 
[task 2020-03-01T12:04:40.125Z] 12:04:40     INFO - Buffered messages finished
[task 2020-03-01T12:04:40.126Z] 12:04:40     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_bug656379-2.html | Button 2 should be hovered after mousemove over button2 - got false, expected true
[task 2020-03-01T12:04:40.126Z] 12:04:40     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:383:14
[task 2020-03-01T12:04:40.126Z] 12:04:40     INFO -     tests@dom/events/test/test_bug656379-2.html:80:5
[task 2020-03-01T12:04:40.127Z] 12:04:40     INFO -     execNext@dom/events/test/test_bug656379-2.html:101:30
[task 2020-03-01T12:04:40.127Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 2 should not be hovered after mousemove over label2 
[task 2020-03-01T12:04:40.129Z] 12:04:40     INFO - Synthesizing mousemove on label2...
[task 2020-03-01T12:04:40.129Z] 12:04:40     INFO - mouseout on HTML > BODY
[task 2020-03-01T12:04:40.129Z] 12:04:40     INFO - mouseover on P#display > LABEL > SPAN#label2
[task 2020-03-01T12:04:40.130Z] 12:04:40     INFO - mouseenter on P#display
[task 2020-03-01T12:04:40.130Z] 12:04:40     INFO - mouseenter on P#display > LABEL
[task 2020-03-01T12:04:40.131Z] 12:04:40     INFO - mouseenter on P#display > LABEL > SPAN#label2
[task 2020-03-01T12:04:40.132Z] 12:04:40     INFO - mousemove on P#display > LABEL > SPAN#label2
[task 2020-03-01T12:04:40.133Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 1 should not be hovered after mousemove over label2 
[task 2020-03-01T12:04:40.133Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 1 should not be hovered after mousemove over label2 

And same for bug 1545222:

[task 2020-03-01T04:57:03.470Z] 04:57:03     INFO - TEST-START | dom/events/test/test_bug656379-2.html
[task 2020-03-01T04:57:03.526Z] 04:57:03     INFO - TEST-INFO | started process screentopng
[task 2020-03-01T04:57:03.853Z] 04:57:03     INFO - TEST-INFO | screentopng: exit 0
[task 2020-03-01T04:57:03.853Z] 04:57:03     INFO - Buffered messages logged at 04:57:03
[task 2020-03-01T04:57:03.853Z] 04:57:03     INFO - must wait for load
[task 2020-03-01T04:57:03.854Z] 04:57:03     INFO - mousemove on P#display > LABEL#label1
[task 2020-03-01T04:57:03.854Z] 04:57:03     INFO - Buffered messages finished
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_bug656379-2.html | Button 1 should be hovered after mousemove over label1 - got false, expected true
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:383:14
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO -     tests@dom/events/test/test_bug656379-2.html:58:5
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO -     execNext@dom/events/test/test_bug656379-2.html:92:30
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_bug656379-2.html | Label 1 should be hovered after mousemove over label1 - got false, expected true
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:383:14
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO -     tests@dom/events/test/test_bug656379-2.html:60:5
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO -     execNext@dom/events/test/test_bug656379-2.html:92:30
[task 2020-03-01T04:57:03.858Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 2 should not be hovered after mousemove over label1 
[task 2020-03-01T04:57:03.859Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 2 should not be hovered after mousemove over label1 
[task 2020-03-01T04:57:03.859Z] 04:57:03     INFO - mousemove on P#display > LABEL > INPUT#button2
[task 2020-03-01T04:57:03.859Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 1 should not be hovered after mousemove over button2 
[task 2020-03-01T04:57:03.860Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 1 should not be hovered after mousemove over button2 
[task 2020-03-01T04:57:03.861Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 2 should be hovered after mousemove over button2 
[task 2020-03-01T04:57:03.861Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 2 should not be hovered after mousemove over label2 
[task 2020-03-01T04:57:03.862Z] 04:57:03     INFO - mousemove on P#display > LABEL > SPAN#label2
[task 2020-03-01T04:57:03.863Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 1 should not be hovered after mousemove over label2 
[task 2020-03-01T04:57:03.865Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 1 should not be hovered after mousemove over label2 
[task 2020-03-01T04:57:03.865Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 2 should be hovered after mousemove over label2 
[task 2020-03-01T04:57:03.867Z] 04:57:03     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 2 should be hovered after mousemove over label2 
[task 2020-03-01T04:57:03.867Z] 04:57:03     INFO - GECKO(2405) | MEMORY STAT | vsize 2617MB | residentFast 189MB | heapAllocated 34MB
[task 2020-03-01T04:57:03.868Z] 04:57:03     INFO - TEST-OK | dom/events/test/test_bug656379-2.html | took 65ms

In those cases, mousemove events are fired as expected. The :hover state is set by EventStateManager::PreHandleEvent() -> EventStateManager::GenerateMouseEnterExit() -> EventStateManager::NotifyMouseOver((). I.e., the state is updated synchronously before dispathcing mousemove event at least in DOM code.

On the other hand, Element::Matches() goes into Stylo.

Emilio, is all resoucre about :hover state in stylo updated synchronously when EventStateManager updeates it?

Blocks: 1545222
Flags: needinfo?(emilio)

Updated the log for this bug with mouseenter, mouseleave, mouseover and mouseout.

Oddly, after mousemove, unexpected mouseout and mouseleave are fired, that must be the cause of this bug.

[task 2020-03-01T12:04:40.119Z] 12:04:40     INFO - mousemove on P#display > LABEL > INPUT#button2
[task 2020-03-01T12:04:40.120Z] 12:04:40     INFO - mouseout on P#display > LABEL > INPUT#button2
[task 2020-03-01T12:04:40.120Z] 12:04:40     INFO - mouseleave on P#display > LABEL > INPUT#button2
[task 2020-03-01T12:04:40.120Z] 12:04:40     INFO - mouseleave on P#display > LABEL
[task 2020-03-01T12:04:40.122Z] 12:04:40     INFO - mouseleave on P#display
[task 2020-03-01T12:04:40.123Z] 12:04:40     INFO - mouseover on HTML > BODY
[task 2020-03-01T12:04:40.123Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Button 1 should not be hovered after mousemove over button2 
[task 2020-03-01T12:04:40.124Z] 12:04:40     INFO - TEST-PASS | dom/events/test/test_bug656379-2.html | Label 1 should not be hovered after mousemove over button2 
[task 2020-03-01T12:04:40.125Z] 12:04:40     INFO - Buffered messages finished
[task 2020-03-01T12:04:40.126Z] 12:04:40     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_bug656379-2.html | Button 2 should be hovered after mousemove over button2 - got false, expected true
[task 2020-03-01T12:04:40.126Z] 12:04:40     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:383:14
[task 2020-03-01T12:04:40.126Z] 12:04:40     INFO -     tests@dom/events/test/test_bug656379-2.html:80:5
[task 2020-03-01T12:04:40.127Z] 12:04:40     INFO -     execNext@dom/events/test/test_bug656379-2.html:101:30
Flags: needinfo?(emilio)

::Matches(":hover") synchronously reflects the event state flag, yeah.

Thanks, and also according to comment 30, it seems that there is an unexpected synthesized mousemove event which caused mouseout and mouseleave. I guess, it could be caused by the style change by :hover state change. Although I've not investigated whether another synthesized mouse move will occur later, this might detect an existing bug rather than bug of the test.
https://searchfox.org/mozilla-central/search?q=symbol:_ZN7mozilla9PresShell19SynthesizeMouseMoveEb&redirect=false

The reason of intermittent failure of test_bug656379-2.html is, synthesized
mousemove event coming from the parent process causes mouseout and
mouseleave events of the last synthesized mousemove in the test. The
reason is, synthesized mousemove for tests make PresShell in the content
process record the cursor location, but won't make it PresShell in the
parent process do it. Therefore, if synthesized mousemove in parent process
may be fired outdated mouse cursor location and PresShell treats it as normal
mousemove, then, tests may get unexpected :hover state.

This patch makes WidgetEvent::mFlags have a flag to indicate whether it
came from another process. Then, makes PresShell::HandleEvent() does not
treat synthesized mousemove events coming from another process as-is.
Finally, instead, make it try to fire synthesized mousemove in the process
with the existing path. (That means that if the root PresShell in the
content process does not store last mouse location, the coming mousemove
event is just discarded.)

Assignee: nobody → masayuki
Status: NEW → ASSIGNED
Attachment #9130702 - Attachment description: Bug 1569512 - Make `PresShell` respect the last mouse cursor location when `mousemove` event comes from another process r=smaug! → Bug 1569512 - Make `PresShell` ignore synthesized `mousemove` events coming from another process if the child process stores mouse location of synthesized mouse events for tests r=smaug
Pushed by masayuki@d-toybox.com: https://hg.mozilla.org/integration/autoland/rev/9f1416f188e7 Make `PresShell` ignore synthesized `mousemove` events coming from another process if the child process stores mouse location of synthesized mouse events for tests r=smaug
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla76

The patch landed in nightly and beta is affected.
:masayuki, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(masayuki)

The patch touched main path of event handling so that it's too risky.

Flags: needinfo?(masayuki)
Regressions: 1622667
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: