1714285 - Intermittent dom/events/test/test_coalesce_mousewheel.html | Should have gotten 1 wheel event - got 2, expected 1

Status: RESOLVED FIXED

(Core :: DOM: UI Events & Focus Handling, defect, P3)

Description

[Treeherder Bug Filer]

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=341602906&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KaI_SPOoSuOcGoxUafcjzg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KaI_SPOoSuOcGoxUafcjzg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2021-06-03T03:20:41.152Z] 03:20:41     INFO - TEST-START | dom/events/test/test_coalesce_mousewheel.html
[task 2021-06-03T03:20:42.555Z] 03:20:42     INFO - GECKO(9876) | MEMORY STAT | vsize 601MB | vsizeMaxContiguous 1293MB | residentFast 59MB | heapAllocated 5MB
[task 2021-06-03T03:20:42.557Z] 03:20:42     INFO - TEST-OK | dom/events/test/test_coalesce_mousewheel.html | took 1407ms
[task 2021-06-03T03:20:42.616Z] 03:20:42     INFO - TEST-START | Shutdown
[task 2021-06-03T03:20:42.617Z] 03:20:42     INFO - Passed:  12
[task 2021-06-03T03:20:42.617Z] 03:20:42     INFO - Failed:  0
[task 2021-06-03T03:20:42.618Z] 03:20:42     INFO - Todo:    4
[task 2021-06-03T03:20:42.618Z] 03:20:42     INFO - Mode:    e10s
[task 2021-06-03T03:20:42.618Z] 03:20:42     INFO - Slowest: 1407ms - /tests/dom/events/test/test_coalesce_mousewheel.html
[task 2021-06-03T03:20:42.618Z] 03:20:42     INFO - SimpleTest START Loop 2
<...>
[task 2021-06-03T03:21:25.155Z] 03:21:25     INFO - SimpleTest START Loop 9
[task 2021-06-03T03:21:25.155Z] 03:21:25     INFO - TEST-START | dom/events/test/test_coalesce_mousewheel.html
[task 2021-06-03T03:21:25.356Z] 03:21:25     INFO - TEST-INFO | started process screenshot
[task 2021-06-03T03:21:25.435Z] 03:21:25     INFO - TEST-INFO | screenshot: exit 0
[task 2021-06-03T03:21:25.435Z] 03:21:25     INFO - Buffered messages logged at 03:21:25
[task 2021-06-03T03:21:25.435Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | A valid string reason is expected 
[task 2021-06-03T03:21:25.435Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Reason cannot be empty 
[task 2021-06-03T03:21:25.436Z] 03:21:25     INFO - TEST-FAIL | dom/events/test/test_coalesce_mousewheel.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Make sure we got all events. 
[task 2021-06-03T03:21:25.436Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Should have gotten 1 wheel event 
[task 2021-06-03T03:21:25.436Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | A valid string reason is expected 
[task 2021-06-03T03:21:25.436Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Reason cannot be empty 
[task 2021-06-03T03:21:25.436Z] 03:21:25     INFO - TEST-FAIL | dom/events/test/test_coalesce_mousewheel.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Make sure we got all events. 
[task 2021-06-03T03:21:25.436Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Should have gotten 1 wheel event 
[task 2021-06-03T03:21:25.436Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | A valid string reason is expected 
[task 2021-06-03T03:21:25.436Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Reason cannot be empty 
[task 2021-06-03T03:21:25.437Z] 03:21:25     INFO - TEST-FAIL | dom/events/test/test_coalesce_mousewheel.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Make sure we got all events. 
[task 2021-06-03T03:21:25.437Z] 03:21:25     INFO - Buffered messages finished
[task 2021-06-03T03:21:25.437Z] 03:21:25     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_coalesce_mousewheel.html | Should have gotten 1 wheel event - got 2, expected 1
[task 2021-06-03T03:21:25.437Z] 03:21:25     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-06-03T03:21:25.437Z] 03:21:25     INFO -     runTests@dom/events/test/test_coalesce_mousewheel.html:101:7
[task 2021-06-03T03:21:25.437Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | A valid string reason is expected 
[task 2021-06-03T03:21:25.437Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Reason cannot be empty 
[task 2021-06-03T03:21:25.437Z] 03:21:25     INFO - TEST-FAIL | dom/events/test/test_coalesce_mousewheel.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Make sure we got all events. 
[task 2021-06-03T03:21:25.438Z] 03:21:25     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Should have got 3 wheel event 
[task 2021-06-03T03:21:25.438Z] 03:21:25     INFO - GECKO(6560) | MEMORY STAT | vsize 595MB | vsizeMaxContiguous 1293MB | residentFast 61MB | heapAllocated 5MB
[task 2021-06-03T03:21:25.443Z] 03:21:25     INFO - TEST-OK | dom/events/test/test_coalesce_mousewheel.html | took 293ms
[task 2021-06-03T03:21:25.474Z] 03:21:25     INFO - TEST-START | Shutdown
[task 2021-06-03T03:21:25.474Z] 03:21:25     INFO - Passed:  107
[task 2021-06-03T03:21:25.474Z] 03:21:25     INFO - Failed:  1
[task 2021-06-03T03:21:25.474Z] 03:21:25     INFO - Todo:    36
[task 2021-06-03T03:21:25.475Z] 03:21:25     INFO - Mode:    e10s
[task 2021-06-03T03:21:25.475Z] 03:21:25     INFO - Slowest: 1417ms - /tests/dom/events/test/test_coalesce_mousewheel.html
[task 2021-06-03T03:21:25.475Z] 03:21:25     INFO - SimpleTest START Loop 10
[task 2021-06-03T03:21:25.475Z] 03:21:25     INFO - TEST-START | dom/events/test/test_coalesce_mousewheel.html

Comment 1

[Iulian Moraru]

This started to fail on tier 2 jobs: Fail log

Comment 2

[Bas Schouten (:bas.schouten)]

I suspect we'll just want to skip this on the TV platform. Correct me if I'm wrong Botond but I don't think it really applies to that platform?

Comment 3

[Botond Ballo [:botond]]

TV isn't really a platform; it's a special job that runs on commits that add or modify tests, and runs that test a large number of times, to try and detect intermittent failures early.

So, the fact that this test failed in the TV job suggests that there's an issue causing an intermittent failure, and we'll likely see it fail intermittently as part of regular test runs going forward. Whether it's worth investigating will depend on the frequency.

The main contribution of the TV job is that it tells us what commit introduced the intermittent failure, rather than having to eyeball pushlogs and guess.

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1712726

Comment 5

[Intermittent Failures Robot]

12 failures in 3065 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 12

Platform and build breakdown:

• linux1804-64: 2
  • opt: 1
  • debug: 1
• linux1804-64-qr: 2
  • opt: 1
  • debug: 1
• windows10-32: 1
  • opt: 1
• macosx1014-64-qr: 4
  • opt: 2
  • debug: 2
• macosx1015-64-shippable-qr: 3
  • opt: 3

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

Comment 6

[Intermittent Failures Robot]

12 failures in 3502 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 10
• mozilla-central: 2

Platform and build breakdown:

• macosx1015-64-shippable-qr: 4
  • opt: 4
• linux1804-64-asan: 1
  • opt: 1
• windows10-32: 2
  • opt: 2
• linux1804-64-qr: 2
  • opt: 1
  • debug: 1
• macosx1015-64-qr: 1
  • debug: 1
• windows10-64-qr: 1
  • opt: 1
• windows10-64-shippable-qr: 1
  • opt: 1

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

Comment 7

[Atila Butkovits]

Started failing on tier 1 jobs: Failure log

Comment 8

[Intermittent Failures Robot]

16 failures in 2888 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

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

Platform and build breakdown:

• linux1804-64-qr: 5
  • debug: 5
• macosx1015-64-shippable-qr: 5
  • opt: 5
• windows10-32: 2
  • opt: 1
  • debug: 1
• macosx1015-64-qr: 1
  • opt: 1
• windows10-64-shippable-qr: 2
  • opt: 2
• windows10-32-shippable: 1
  • opt: 1

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

Comment 9

[Intermittent Failures Robot]

12 failures in 3115 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 5
• autoland: 7

Platform and build breakdown:

• windows10-32-shippable-qr: 3
  • opt: 3
• windows10-64: 1
  • debug: 1
• linux1804-64-shippable-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1
• linux1804-64-qr: 1
  • opt: 1
• windows10-32-qr: 3
  • opt: 2
  • debug: 1
• macosx1015-64-qr: 1
  • opt: 1
• linux1804-64: 1
  • opt: 1

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

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3
• mozilla-central: 2
• try: 2

Platform and build breakdown:

• macosx1015-64-shippable-qr: 2
  • opt: 2
• windows10-32-shippable-qr: 1
  • opt: 1
• windows10-32-qr: 1
  • opt: 1
• windows10-64-shippable: 1
  • opt: 1
• windows10-64-asan-qr: 1
  • opt: 1
• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1714285&startday=2021-06-28&endday=2021-07-04&tree=all

Comment 11

[Intermittent Failures Robot]

19 failures in 2387 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 12
• mozilla-central: 6
• try: 1

Platform and build breakdown:

• linux1804-64-qr: 3
  • debug: 2
  • opt: 1
• linux1804-64-tsan: 4
  • opt: 4
• macosx1015-64-shippable-qr: 4
  • opt: 4
• windows10-32-qr: 2
  • opt: 2
• windows10-32-shippable-qr: 4
  • opt: 4
• macosx1015-64-qr: 2
  • debug: 2

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

Comment 12

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

FYI: The test started to run Fission-xorigin tests again (bug 1715083). Therefore, the frequency of this intermittent failure may become higher.

Comment 13

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

I tried to rewrite the test as mochitest-chrome to synthesize wheel events in the main process and avoid unexpected IPCs and flushing reflows while synthesizing a set of wheel events. However, they fail more frequently!
https://treeherder.mozilla.org/jobs?repo=try&collapsedPushes=931912%2C931897&selectedTaskRun=GfjgG6_kRFmoMBM7k2Lw1g.0&revision=1ea9a26a4d697a8d9eb07a31fb243d37ebc3f13f

On the other hand, I checked BrowserChild::RecvMouseWheelEvent():
https://searchfox.org/mozilla-central/rev/c0fc8c4852e927b0ae75d893d35772b8c60ee06b/dom/ipc/BrowserChild.cpp#1846-1865

Then, it considers whether it dispatches an eWheel event or not only from the next IPC message in the remote process. It's odd. Is it really guaranteed that synthesized wheel events continuously from JS are coalesced into an event? It seems that we cannot test this strictly.

Comment 14

[Olli Pettay [:smaug][[e-mail]]]

Testing this is hard. I think Bas had to go through couple of iteration when tweaking the test. He might have some ideas how to make the test
less fragile or how to make it deal with different number wheel events.

Comment 15

[Intermittent Failures Robot]

40 failures in 2224 pushes (0.018 failures/push) were associated with this bug in the last 7 days.

This is the #26 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:

• try: 1
• mozilla-central: 13
• autoland: 24
• mozilla-esr91: 1
• mozilla-beta: 1

Platform and build breakdown:

• windows10-32-shippable-qr: 4
  • opt: 4
• macosx1015-64-shippable-qr: 7
  • opt: 7
• windows10-64-qr: 2
  • debug: 1
  • opt: 1
• macosx1015-64-qr: 15
  • debug: 14
  • opt: 1
• linux1804-64-qr: 4
  • debug: 2
  • opt: 2
• linux1804-64-shippable-qr: 6
  • opt: 6
• windows10-64-shippable-qr: 1
  • opt: 1
• linux1804-64-tsan: 1
  • opt: 1

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

Comment 16

[Intermittent Failures Robot]

15 failures in 640 pushes (0.023 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-beta: 1

Platform and build breakdown:

• windows10-64-qr: 3
  • debug: 1
  • opt: 2
• linux1804-64-qr: 2
  • opt: 2
• macosx1015-64-qr: 7
  • opt: 2
  • debug: 5
• linux1804-64-shippable-qr: 1
  • opt: 1
• windows10-64-shippable-qr: 1
  • opt: 1
• windows10-32-shippable-qr: 1
  • opt: 1

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

Comment 17

[Bas Schouten (:bas.schouten)]

(In reply to Olli Pettay [:smaug] (vacation July 18 - 31) from comment #14)

Testing this is hard. I think Bas had to go through couple of iteration when tweaking the test. He might have some ideas how to make the test
less fragile or how to make it deal with different number wheel events.

Not really, when I had to tweak this to become less fragile the challenge I was dealing with was making sure all the events had arrived before measuring. In this case it appears the events are delivered 'separately' to the content process. I'm not sure what could cause that and it never occurred locally :(.

Comment 18

[Bas Schouten (:bas.schouten)]

(In reply to Masayuki Nakano [:masayuki] (he/him)(JST, +0900) from comment #13)

I tried to rewrite the test as mochitest-chrome to synthesize wheel events in the main process and avoid unexpected IPCs and flushing reflows while synthesizing a set of wheel events. However, they fail more frequently!
https://treeherder.mozilla.org/jobs?repo=try&collapsedPushes=931912%2C931897&selectedTaskRun=GfjgG6_kRFmoMBM7k2Lw1g.0&revision=1ea9a26a4d697a8d9eb07a31fb243d37ebc3f13f

On the other hand, I checked BrowserChild::RecvMouseWheelEvent():
https://searchfox.org/mozilla-central/rev/c0fc8c4852e927b0ae75d893d35772b8c60ee06b/dom/ipc/BrowserChild.cpp#1846-1865

Then, it considers whether it dispatches an eWheel event or not only from the next IPC message in the remote process. It's odd. Is it really guaranteed that synthesized wheel events continuously from JS are coalesced into an event? It seems that we cannot test this strictly.

I had the same impression but people really really (understandably) wanted me to add a test for this when I made changes to coalescion, and none existed at that point :-).

Comment 19

[Intermittent Failures Robot]

64 failures in 2940 pushes (0.022 failures/push) were associated with this bug in the last 7 days.

This is the #12 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: 48
• mozilla-central: 12
• mozilla-beta: 4

Platform and build breakdown:

• macosx1015-64-qr: 28
  • debug: 24
  • opt: 4
• linux1804-64-tsan: 1
  • opt: 1
• linux1804-64-shippable-qr: 10
  • opt: 10
• macosx1015-64-shippable-qr: 3
  • opt: 3
• windows10-64-qr: 8
  • debug: 4
  • opt: 4
• linux1804-64-qr: 5
  • opt: 3
  • debug: 2
• windows10-64-shippable-qr: 4
  • opt: 4
• windows10-32-shippable-qr: 4
  • opt: 4
• windows10-32-qr: 1
  • debug: 1

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

Comment 20

[Iulian Moraru]

Update:
There have been 54 failures within the last 7 days:
• 4 failures on Linux 18.04 x64 WebRender opt
• 2 failures on Linux 18.04 x64 WebRender debug
• 10 failures on Linux 18.04 x64 WebRender Shippable opt
• 3 failures on OS X 10.15 WebRender opt
• 19 failures on OS X 10.15 WebRender debug
• 2 failures on OS X 10.15 WebRender Shippable opt
• 1 failures on Windows 10 x86 WebRender debug
• 5 failures on Windows 10 x64 WebRender debug
• 4 failures on Windows 10 x64 WebRender opt
• 4 failures on Windows 10 x64 WebRender Shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=346398769&repo=mozilla-central&lineNumber=4797

[task 2021-07-26T22:40:28.251Z] 22:40:28     INFO - TEST-START | dom/events/test/test_coalesce_mousewheel.html
[task 2021-07-26T22:40:28.260Z] 22:40:28     INFO - GECKO(2669) | [Child 2673, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-07-26T22:40:28.270Z] 22:40:28     INFO - GECKO(2669) | [Child 2673, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-07-26T22:40:28.288Z] 22:40:28     INFO - GECKO(2669) | [Parent 2669, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:2928
[task 2021-07-26T22:40:28.318Z] 22:40:28     INFO - GECKO(2669) | [Child 2829, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3357
[task 2021-07-26T22:40:28.330Z] 22:40:28     INFO - GECKO(2669) | [Child 2829, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4438
[task 2021-07-26T22:40:28.450Z] 22:40:28     INFO - GECKO(2669) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/_b/_62qvbkx445dym012mj98plm000014/T/tmpu94h8ihb.mozrunner/runtests_leaks_tab_pid2833.log
[task 2021-07-26T22:40:28.450Z] 22:40:28     INFO - GECKO(2669) | [2833, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:250
[task 2021-07-26T22:40:28.530Z] 22:40:28     INFO - TEST-INFO | started process screencapture
[task 2021-07-26T22:40:28.638Z] 22:40:28     INFO - TEST-INFO | screencapture: exit 0
[task 2021-07-26T22:40:28.639Z] 22:40:28     INFO - Buffered messages logged at 22:40:28
[task 2021-07-26T22:40:28.639Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | A valid string reason is expected 
[task 2021-07-26T22:40:28.639Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Reason cannot be empty 
[task 2021-07-26T22:40:28.640Z] 22:40:28     INFO - TEST-FAIL | dom/events/test/test_coalesce_mousewheel.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Make sure we got all events. 
[task 2021-07-26T22:40:28.640Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Should have gotten 1 wheel event 
[task 2021-07-26T22:40:28.641Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | A valid string reason is expected 
[task 2021-07-26T22:40:28.641Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Reason cannot be empty 
[task 2021-07-26T22:40:28.641Z] 22:40:28     INFO - TEST-FAIL | dom/events/test/test_coalesce_mousewheel.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Make sure we got all events. 
[task 2021-07-26T22:40:28.642Z] 22:40:28     INFO - Buffered messages finished
[task 2021-07-26T22:40:28.642Z] 22:40:28     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_coalesce_mousewheel.html | Should have gotten 1 wheel event - got 2, expected 1
[task 2021-07-26T22:40:28.642Z] 22:40:28     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-07-26T22:40:28.642Z] 22:40:28     INFO -     runTests@dom/events/test/test_coalesce_mousewheel.html?currentTestURL=dom%2Fevents%2Ftest%2Ftest_coalesce_mousewheel.html&closeWhenDone=1&showTestReport=false&expected=pass:102:7
[task 2021-07-26T22:40:28.643Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | A valid string reason is expected 
[task 2021-07-26T22:40:28.643Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Reason cannot be empty 
[task 2021-07-26T22:40:28.644Z] 22:40:28     INFO - TEST-FAIL | dom/events/test/test_coalesce_mousewheel.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Make sure we got all events. 
[task 2021-07-26T22:40:28.644Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Should have gotten 1 wheel event 
[task 2021-07-26T22:40:28.678Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | A valid string reason is expected 
[task 2021-07-26T22:40:28.679Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Reason cannot be empty 
[task 2021-07-26T22:40:28.679Z] 22:40:28     INFO - TEST-FAIL | dom/events/test/test_coalesce_mousewheel.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Make sure we got all events. 
[task 2021-07-26T22:40:28.848Z] 22:40:28     INFO - TEST-PASS | dom/events/test/test_coalesce_mousewheel.html | Should have got 3 wheel event 
[task 2021-07-26T22:40:28.896Z] 22:40:28     INFO - GECKO(2669) | MEMORY STAT | vsize 6630MB | residentFast 86MB | heapAllocated 7MB
[task 2021-07-26T22:40:28.910Z] 22:40:28     INFO - TEST-OK | dom/events/test/test_coalesce_mousewheel.html | took 659ms
[task 2021-07-26T22:40:28.927Z] 22:40:28     INFO - GECKO(2669) | [Parent 2669, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3896
[task 2021-07-26T22:40:28.928Z] 22:40:28     INFO - GECKO(2669) | [Parent 2669, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3896
[task 2021-07-26T22:40:28.928Z] 22:40:28     INFO - GECKO(2669) | [Parent 2669, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:2928
[task 2021-07-26T22:40:28.931Z] 22:40:28     INFO - GECKO(2669) | [Child 2830, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm:762
[task 2021-07-26T22:40:28.932Z] 22:40:28     INFO - GECKO(2669) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-07-26T22:40:28.932Z] 22:40:28     INFO - GECKO(2669) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-07-26T22:40:28.942Z] 22:40:28     INFO - TEST-START | dom/events/test/test_continuous_wheel_events.html

Comment 21

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

(In reply to Bas Schouten (:bas.schouten) from comment #18)

and none existed at that point :-).

Wow, that's big hint for me. I checked what IPC message comes unexpectedly with the chrome test, then, I see PWindowGlobal::Msg_RawMessage__ID, it's used by actors:
https://searchfox.org/mozilla-central/search?q=SendRawMessage&path=&case=false&regexp=false

On the other hand, I'm currently trying to check with the plain test. However, I've not reproduced this intermittent failure yet. Keep trying...

Comment 22

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

Hmm, various IPC messages appear...:

• PHttpChannel::Msg_DeleteSelf
• PBrowser::Msg_SynthMouseMoveEvent
• PContent::Msg_FlushFOGData
• PContent::Msg_AddPermission
• PContent::Msg_PreferenceUpdate
• PContent::Msg_GMPsChanged
• PContent::Msg_NotifyVisited

Comment 23

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

I think that we can ignore those messages if received event is synthesized for tests.

• PHttpChannel::Msg_DeleteSelf

I think that this can be ignored in actual user input because it's to destroy an HTTP session, which perhaps doesn't unpdate anything.

• PBrowser::Msg_SynthMouseMoveEvent

This updates style. So, we shouldn't ignore this.

• PContent::Msg_FlushFOGData

This is a message for telemetry. So, we can ignore this.

• PContent::Msg_AddPermission

I'm not sure this case yet.

• PContent::Msg_PreferenceUpdate

I think that pref being updated between wheel operation shouldn't affect web content. So, this must be able to be ignored.

• PContent::Msg_GMPsChanged

I'm not sure this message yet.

• PContent::Msg_NotifyVisited

I think that we can ignore this message because this must not repaint content synchronous.

Comment 24

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

Attachment: Bug 1714285 - part 1: Make `BrowserChild` ignore allow-listed IPC messages when wheel events coalesced is being tested r=smaug!

The following IPC messages may be inserted before wheel event message
accidentally.

• PHttpChannel::Msg_DeleteSelf
• PBrowser::Msg_SynthMouseMoveEvent
• PContent::Msg_FlushFOGData
• PContent::Msg_AddPermission
• PContent::Msg_PreferenceUpdate
• PContent::Msg_GMPsChanged
• PContent::Msg_NotifyVisited

Only PBrowser::Msg_SynthMouseMoveEvent can be avoided by the test with
moving native mouse cursor first, but the others are really accidental
messages for the test. For avoiding current intermittent failures, we should
make BrowserChild::RecvMouseWheelEvent ignore the unexpected messages
only while a test is running for testing mouse wheel coalescing.

Perhaps, PContent::Msg_FlushFOGData, PContent::Msg_PreferenceUpdate and
PContent::Msg_NotifyVisited are also safe for real user input because
they must not affect web content, but in this bug, we shouldn't change any
real behavior.

Comment 25

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

Attachment: Bug 1714285 - Make `test_coalesce_mousewheel.html` retry to get ideal result unless `wheel` event values are wrong r=smaug!

Even with the previous patch, the test may fail if next wheel event is not
in the queue. Therefore, we should make each test retry until getting
expected result if deltaMode and deltaY values of wheel events are not
wrong.

Depends on D121060

Comment 26

[Intermittent Failures Robot]

17 failures in 622 pushes (0.027 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 9
• mozilla-beta: 2
• mozilla-central: 6

Platform and build breakdown:

• windows10-64-qr: 1
  • debug: 1
• windows10-32-shippable-qr: 2
  • opt: 2
• macosx1015-64-qr: 7
  • debug: 6
  • opt: 1
• linux1804-64-shippable-qr: 2
  • opt: 2
• linux1804-64-qr: 2
  • opt: 2
• macosx1015-64-shippable-qr: 1
  • opt: 1
• linux1804-64-tsan: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • debug: 1

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

Comment 27

[Intermittent Failures Robot]

48 failures in 3131 pushes (0.015 failures/push) were associated with this bug in the last 7 days.

This is the #24 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 34
• mozilla-central: 11
• try: 1
• mozilla-beta: 2

Platform and build breakdown:

• macosx1015-64-qr: 18
  • debug: 17
  • opt: 1
• windows10-64-qr: 4
  • debug: 4
• linux1804-64-qr: 5
  • opt: 4
  • debug: 1
• linux1804-64-shippable-qr: 9
  • opt: 9
• macosx1015-64-shippable-qr: 4
  • opt: 4
• linux1804-64-tsan: 2
  • opt: 2
• windows10-32-shippable-qr: 2
  • opt: 2
• windows10-64-2004-qr: 4
  • debug: 4

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

Comment 28

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/45557f9d3333
Make `test_coalesce_mousewheel.html` retry to get ideal result unless `wheel` event values are wrong r=smaug

Comment 29

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/45557f9d3333

Comment 31

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr91/rev/16121fa8c8f5

Comment 32

[Intermittent Failures Robot]

9 failures in 2829 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 6
• mozilla-central: 2
• mozilla-esr91: 1

Platform and build breakdown:

• windows10-64-2004-qr: 5
  • opt: 1
  • debug: 4
• macosx1015-64-qr: 2
  • debug: 2
• windows10-64-2004-shippable-qr: 1
  • opt: 1
• windows10-32-shippable-qr: 1
  • opt: 1

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

Comment 33

[Intermittent Failures Robot]

1 failures in 2580 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 1

Platform and build breakdown:

• windows10-32-shippable-qr: 1
  • opt: 1

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