1685004 - Intermittent gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a mouselongtap - got "mouseover", expected "mouselongtap"

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=325798909&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UyVBOzJeQUuVm4LyI9vR6g/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-01-05T00:10:27.152Z] 00:10:27     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a touchstart 
[task 2021-01-05T00:10:27.152Z] 00:10:27     INFO - Buffered messages finished
[task 2021-01-05T00:10:27.152Z] 00:10:27     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a mouselongtap - got "mouseover", expected "mouselongtap"
[task 2021-01-05T00:10:27.152Z] 00:10:27     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-01-05T00:10:27.152Z] 00:10:27     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:440:18
[task 2021-01-05T00:10:27.152Z] 00:10:27     INFO -     recordEvent@gfx/layers/apz/test/mochitest/helper_long_tap.html:46:11
[task 2021-01-05T00:10:27.152Z] 00:10:27     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a touchend - got "mouseenter", expected "touchend"
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:440:18
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO -     recordEvent@gfx/layers/apz/test/mochitest/helper_long_tap.html:49:17
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a mouseover - got "touchend", expected "mouseover"
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:440:18
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO -     recordEvent@gfx/layers/apz/test/mochitest/helper_long_tap.html:50:17
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO - GECKO(4512) | [Child 5792, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-01-05T00:10:27.153Z] 00:10:27     INFO - GECKO(4512) | [Child 5792, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a mouseenter - got "mousemove", expected "mouseenter"
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:440:18
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO -     recordEvent@gfx/layers/apz/test/mochitest/helper_long_tap.html:51:17
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO - GECKO(4512) | helper_long_tap.html | got MozAfterPaint: 0,0,0,0
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO - GECKO(4512) | helper_long_tap.html | Dispatching 0 onpaint listeners
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a mousemove - got "mouseout", expected "mousemove"
[task 2021-01-05T00:10:27.154Z] 00:10:27     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-01-05T00:10:27.155Z] 00:10:27     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:440:18
[task 2021-01-05T00:10:27.155Z] 00:10:27     INFO -     recordEvent@gfx/layers/apz/test/mochitest/helper_long_tap.html:52:17
[task 2021-01-05T00:10:27.155Z] 00:10:27     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-05T00:10:27.155Z] 00:10:27     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a contextmenu - got "mouseleave", expected "contextmenu"
[task 2021-01-05T00:10:27.155Z] 00:10:27     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-01-05T00:10:27.155Z] 00:10:27     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:440:18
[task 2021-01-05T00:10:27.155Z] 00:10:27     INFO -     recordEvent@gfx/layers/apz/test/mochitest/helper_long_tap.html:53:17```

Comment 1

[Intermittent Failures Robot]

2 failures in 2956 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• windows7-32: 1
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1685004&startday=2021-01-04&endday=2021-01-10&tree=all

Comment 2

[Andreea Pavel [:apavel]]

Hi Steven, can the recent failures here be from bug 1677774 ?

Comment 3

[Intermittent Failures Robot]

34 failures in 3891 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

This is the #33 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 27
• mozilla-central: 7

Platform and build breakdown:

• windows10-64: 18
  • asan: 18
• windows7-32: 16
  • debug: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1685004&startday=2021-01-25&endday=2021-01-31&tree=all

Comment 4

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 43 failures within the last 7 days:

• 24 failures on Windows 10 x64 asan
• 19 failures on Windows 7 debug

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=329134595&repo=autoland&lineNumber=18009

[task 2021-02-07T07:08:31.143Z] 07:08:31 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a touchstart
[task 2021-02-07T07:08:31.143Z] 07:08:31 INFO - Buffered messages finished
[task 2021-02-07T07:08:31.143Z] 07:08:31 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_touchevents-2.html | helper_long_tap.html | Got a mouselongtap - got "mouseover", expected "mouselongtap"
[task 2021-02-07T07:08:31.143Z] 07:08:31 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-02-07T07:08:31.143Z] 07:08:31 INFO - spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:423:18
[task 2021-02-07T07:08:31.143Z] 07:08:31 INFO - recordEvent@gfx/layers/apz/test/mochitest/helper_long_tap.html:46:11
[task 2021-02-07T07:08:31.144Z] 07:08:31 INFO - Not taking screenshot here: see the one that was previously logged

Comment 5

[Intermittent Failures Robot]

45 failures in 3966 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #19 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 33
• mozilla-central: 9
• try: 3

Platform and build breakdown:

• windows10-64: 27
  • asan: 26
  • debug: 1
• windows7-32: 18
  • debug: 18

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1685004&startday=2021-02-01&endday=2021-02-07&tree=all

Comment 6

[Steven MacLeod [:smacleod]]

(In reply to Andreea Pavel [:apavel] from comment #2)

Hi Steven, can the recent failures here be from bug 1677774 ?

I don't think so, unless this used to be an intermittent crash? The most recent changes from bug 1677774 shouldn't change behaviour other than continuing where we used to crash.

Comment 7

[Andreea Pavel [:apavel]]

@Steven, thank you for checking.
@Botond, can you assign someone to take a look?

Comment 8

[Botond Ballo [:botond]]

Sure, I will take a look.

Comment 9

[Intermittent Failures Robot]

43 failures in 4322 pushes (0.01 failures/push) were associated with this bug in the last 7 days.

This is the #20 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 31
• mozilla-central: 11
• try: 1

Platform and build breakdown:

• windows10-64: 23
  • asan: 23
• windows7-32: 19
  • debug: 19
• windows10-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1685004&startday=2021-02-08&endday=2021-02-14&tree=all

Comment 10

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 48 failures within the last 7 days:

• 22 failures on Windows 7 debug
• 26 failures on Windows 10 x64 asan

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=330561739&repo=autoland&lineNumber=11643

Comment 11

[Botond Ballo [:botond]]

It looks like the test is expecting a very specific sequence on events during a long touch-tap, which (on Windows) is:

1. (test code sends TOUCH_CONTACT)
2. touchstart
3. mouselongtap (test code now sends TOUCH_REMOVE)
4. touchend
5. mouseover
6. mouseenter
7. mousemove
8. contextmenu

When an intermittent failure occurs, it instead receives this sequence:

1. (test code sends TOUCH_CONTACT)
2. touchstart
3. mouseover (test code sends TOUCH_REMOVE anyways)
4. mouseenter
5. touchend
6. mousemove
7. mouseout
8. mouseleave

(It may still receive a contextmenu after all this, but it stops listening at this point so it doesn't show in the logs.)

Masayuki, are you aware of any recent change (perhaps around early January, when this intermittent started) related to mouse event handling which could occasionally cause this modified sequence of events?

Comment 12

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)]

I checked review requests around early January, but I have no idea. edgar, do you?

Comment 13

[Botond Ballo [:botond]]

After taking another look, I don't think there's anything fishy about the mouse event sequence. "mouseout" and "mouseleave" look like the counterparts to "mouseover" and "mouseenter" which we would likely also see in the success case if we didn't stop listening.

The salient difference between the sequences in the success vs. failure cases is the absence of the "mouselongtap". Some logging I've added suggests APZ is sending a single-tap rather than a long-tap, suggesting the issue is related to something like a stray touchend event, possibly from the previous test.

Comment 14

[Botond Ballo [:botond]]

(In reply to Botond Ballo [:botond] from comment #13)

suggesting the issue is related to something like a stray touchend event, possibly from the previous test.

Further investigation suggests the touchend event resulting in a single-tap isn't a stray one from the previous test, but the one synthesized by the test itself.

The test asserts that the second event it receives is a mouselongtap, but then synthesizes a touchend regardless.

If it receives an unexpected non-mouselongtap as the second event -- such as a mouseover in this case -- it synthesizes that touchend prematurely, and turns the intended long-tap into a single-tap.

So, the issue seems to be getting a stray / unexpected mouseover. Not sure why that might be happening, but I'm also not sure that it's important for the purpose of the test. We might be able to just ignore it.

Comment 15

[Intermittent Failures Robot]

41 failures in 3737 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #15 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 26
• mozilla-central: 13
• try: 2

Platform and build breakdown:

• windows10-64: 25
  • asan: 25
• windows7-32: 16
  • debug: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1685004&startday=2021-02-15&endday=2021-02-21&tree=all

Comment 16

[Botond Ballo [:botond]]

Couple of updates here:

• The problematic mouseover is not an additional one, but rather the one we expect arrives earlier.
• I'm not exactly sure why; I'm seeing calls to NotifyMouseOver() with aMouseEvent->mMessage being eMouseMove, as well as ePointerGotCapture just before the mouseover arrives. Note, however, that this is before an eMouseMove is generated by FireContextMenuEvents().

I think I should be able to work around this in the test, but it remains to be seen whether the workaround is a satisfactory solution.

Comment 17

[Edgar Chen [:edgar]]

(In reply to Botond Ballo [:botond] from comment #16)

as well as ePointerGotCapture just before the mouseover arrives.

This reminds me that I enabled implicit pointer capture for touch event around January, see bug 1682527, could you try whether setting dom.w3c_pointer_events.implicit_capture to false help, though I am no idea why it affects mouseover event.

Comment 18

[Botond Ballo [:botond]]

(In reply to Edgar Chen [:edgar] from comment #17)

This reminds me that I enabled implicit pointer capture for touch event around January, see bug 1682527, could you try whether setting dom.w3c_pointer_events.implicit_capture to false help, though I am no idea why it affects mouseover event.

Yes, setting this pref to false does seem to resolve the intermittent failure.

Comment 19

[Edgar Chen [:edgar]]

(In reply to Botond Ballo [:botond] from comment #18)

Yes, setting this pref to false does seem to resolve the intermittent failure.

Thanks! So it seems like the ePointerGotCapture somehow triggers the mouseover event. I will take a look.

Comment 20

[Andreea Pavel [:apavel]]

Botond/Edgar this has 180 total failures in the last 30 days. Should it get disabled until there is a fix or leave it enabled?

Comment 21

[Edgar Chen [:edgar]]

Please give me few more days, I am actively debugging this. :-)

Comment 22

[Andreea Pavel [:apavel]]

(In reply to Edgar Chen [:edgar] from comment #21)

Please give me few more days, I am actively debugging this. :-)

Sure, thanks for working on this!

Comment 23

[Edgar Chen [:edgar]]

(In reply to Edgar Chen [:edgar] from comment #19)

So it seems like the ePointerGotCapture somehow triggers the mouseover event. I will take a look.

Err, mouseover isn't from the ePointerGotCapture, it is from a synthesized mousemove event.

Comment 24

[Botond Ballo [:botond]]

Attachment: Bug 1685004 - Work around unexpected event order in helper_long_tap.html. r=edgar

Comment 25

[Botond Ballo [:botond]]

Edgar, I posted a patch which works around the failure.

From an APZ point of view, I think the test is still valid with this change. However, I will leave it up to you if you find it a satisfying fix, or would like to investigate the underlying issue further. (In the latter case, we could still consider landing this patch as a temporary workaround.)

Comment 26

[Edgar Chen [:edgar]]

Thanks, Botond. I was worried about if bug 1682527 causes any regression, but it seems not the case.

The synthesized mousemove is scheduled for layout reflow, I guess there is some timing change after bug 1682527, so make the synthesized mousemove from reflow could possibly happen before the mouselongtap.

Another option is to disable synthesizing mousemove from reflow by setting layout.reflow.synthMouseMove to false to ensure mouseover is generated by the synthesized mousemove for context menu.

Comment 27

[Botond Ballo [:botond]]

Attachment: Bug 1685004 - Disable layout.reflow.synthMouseMove for helper_long_tap.html. r=edgar

Comment 28

[Botond Ballo [:botond]]

(In reply to Edgar Chen [:edgar] from comment #26)

Another option is to disable synthesizing mousemove from reflow by setting layout.reflow.synthMouseMove to false to ensure mouseover is generated by the synthesized mousemove for context menu.

Thanks, let's go with this approach as it's less invasive and allows the test to continue to make more precise assertions.

Here is a Try push showing that it resolves the intermittent.

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5d06025b04a5
Disable layout.reflow.synthMouseMove for helper_long_tap.html. r=edgar

Comment 30

[Alexandru Michis [:malexandru]]

https://hg.mozilla.org/mozilla-central/rev/5d06025b04a5

Comment 31

[Intermittent Failures Robot]

47 failures in 4327 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #17 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 27
• mozilla-central: 20

Platform and build breakdown:

• windows7-32: 13
  • debug: 13
• windows10-64: 34
  • asan: 30
  • debug: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1685004&startday=2021-02-22&endday=2021-02-28&tree=all

Comment 32

[Botond Ballo [:botond]]

The patch that landed did not disable the test, it fixed the intermittent by setting the pref layout.reflow.synthMouseMove=false, which does not affect the validity of the test.

So, unless I'm misunderstanding the reason this was reopened, I think this can be closed.

Comment 33

[Andreea Pavel [:apavel]]

(In reply to Botond Ballo [:botond] from comment #32)

The patch that landed did not disable the test, it fixed the intermittent by setting the pref layout.reflow.synthMouseMove=false, which does not affect the validity of the test.

So, unless I'm misunderstanding the reason this was reopened, I think this can be closed.

Ah, thank you for clarifying.