Closed Bug 1692814 Opened 3 years ago Closed 2 years ago

Intermittent gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js | Test timed out -

Categories

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

Product:
Core
Component:
Panning and Zooming
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
98 Branch
Tracking Flags:
Tracking Status
firefox98 --- fixed

People

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

Details

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

Attachments

(1 file)

Bug 1692814 - Send a click event on the target window to make sure OnEnterNotifyEvent gets called before start dragging on Linux. r?tnikkel!,arai!
48 bytes, text/x-phabricator-request
Details | Review

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=329957017&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/C2sd0W4eSx66iw0gfwpiow/runs/2/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/C2sd0W4eSx66iw0gfwpiow/runs/2/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2021-02-14T23:39:45.759Z] 23:39:45     INFO - TEST-START | gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js
[task 2021-02-14T23:39:47.170Z] 23:39:47     INFO - GECKO(3448) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-02-14T23:39:47.226Z] 23:39:47     INFO - GECKO(3448) | PromiseApzRepaintsFlushed: APZ flush done
[task 2021-02-14T23:39:47.246Z] 23:39:47     INFO - GECKO(3448) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2021-02-14T23:39:47.275Z] 23:39:47     INFO - GECKO(3448) | WaitUntilApzStable: APZ flush done in parent proc
[task 2021-02-14T23:39:47.275Z] 23:39:47     INFO - GECKO(3448) | WaitUntilApzStable: got apz-flush-done in child proc
[task 2021-02-14T23:39:47.275Z] 23:39:47     INFO - GECKO(3448) | WaitUntilApzStable: done promiseFocus
[task 2021-02-14T23:39:47.275Z] 23:39:47     INFO - GECKO(3448) | WaitUntilApzStable: done promiseAllPaintsDone
[task 2021-02-14T23:39:47.276Z] 23:39:47     INFO - GECKO(3448) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-02-14T23:39:47.292Z] 23:39:47     INFO - GECKO(3448) | PromiseApzRepaintsFlushed: APZ flush done
[task 2021-02-14T23:39:47.292Z] 23:39:47     INFO - GECKO(3448) | WaitUntilApzStable: all done
[task 2021-02-14T23:39:47.300Z] 23:39:47     INFO - GECKO(3448) | Starting drag at 1274, 17 from top-left of #
[task 2021-02-14T23:40:30.776Z] 23:40:30     INFO - TEST-INFO | started process screentopng
[task 2021-02-14T23:40:31.047Z] 23:40:31     INFO - TEST-INFO | screentopng: exit 0
[task 2021-02-14T23:40:31.047Z] 23:40:31     INFO - Buffered messages logged at 23:39:45
[task 2021-02-14T23:40:31.047Z] 23:40:31     INFO - Entering test bound 
[task 2021-02-14T23:40:31.047Z] 23:40:31     INFO - Buffered messages logged at 23:39:46
[task 2021-02-14T23:40:31.047Z] 23:40:31     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://mochi.test:8888/browser/gfx/layers/apz/test/mochitest/helper_scroll_thumb_dragging.html" line: 0}]
[task 2021-02-14T23:40:31.047Z] 23:40:31     INFO - Buffered messages finished
[task 2021-02-14T23:40:31.047Z] 23:40:31     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js | Test timed out - ```
Summary: Intermittent [TV] gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js | Test timed out - → Intermittent gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js | Test timed out -

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 3 years ago → 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Update:
There have been 29 failures within the last 7 days:
• 23 failures on Linux 18.04 x64 WebRender opt
• 6 failures on Linux 18.04 x64 WebRender Shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=364066726&repo=autoland&lineNumber=11207

[task 2022-01-13T22:47:43.735Z] 22:47:43     INFO - TEST-START | gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js
[task 2022-01-13T22:47:44.339Z] 22:47:44     INFO - GECKO(742) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2022-01-13T22:47:44.360Z] 22:47:44     INFO - GECKO(742) | PromiseApzRepaintsFlushed: APZ flush done
[task 2022-01-13T22:47:44.392Z] 22:47:44     INFO - GECKO(742) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2022-01-13T22:47:44.394Z] 22:47:44     INFO - GECKO(742) | WaitUntilApzStable: APZ flush done in parent proc
[task 2022-01-13T22:47:44.395Z] 22:47:44     INFO - GECKO(742) | WaitUntilApzStable: got apz-flush-done in child proc
[task 2022-01-13T22:47:44.396Z] 22:47:44     INFO - GECKO(742) | WaitUntilApzStable: done promiseFocus
[task 2022-01-13T22:47:44.397Z] 22:47:44     INFO - GECKO(742) | WaitUntilApzStable: done promiseAllPaintsDone
[task 2022-01-13T22:47:44.398Z] 22:47:44     INFO - GECKO(742) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2022-01-13T22:47:44.417Z] 22:47:44     INFO - GECKO(742) | PromiseApzRepaintsFlushed: APZ flush done
[task 2022-01-13T22:47:44.418Z] 22:47:44     INFO - GECKO(742) | WaitUntilApzStable: all done
[task 2022-01-13T22:47:44.436Z] 22:47:44     INFO - GECKO(742) | Starting drag at 1274, 17 from top-left of #
[task 2022-01-13T22:48:28.754Z] 22:48:28     INFO - TEST-INFO | started process screentopng
[task 2022-01-13T22:48:29.200Z] 22:48:29     INFO - TEST-INFO | screentopng: exit 0
[task 2022-01-13T22:48:29.200Z] 22:48:29     INFO - Buffered messages logged at 22:47:43
[task 2022-01-13T22:48:29.201Z] 22:48:29     INFO - Entering test bound 
[task 2022-01-13T22:48:29.201Z] 22:48:29     INFO - Buffered messages logged at 22:47:44
[task 2022-01-13T22:48:29.201Z] 22:48:29     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://example.org/" line: 0}]
[task 2022-01-13T22:48:29.201Z] 22:48:29     INFO - Buffered messages finished
[task 2022-01-13T22:48:29.201Z] 22:48:29     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js | Test timed out - 
[task 2022-01-13T22:48:29.202Z] 22:48:29     INFO - GECKO(742) | MEMORY STAT | vsize 3138MB | residentFast 346MB | heapAllocated 235MB
[task 2022-01-13T22:48:29.203Z] 22:48:29     INFO - TEST-OK | gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js | took 45023ms
[task 2022-01-13T22:48:29.204Z] 22:48:29     INFO - checking window state
[task 2022-01-13T22:48:29.205Z] 22:48:29     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-01-13T22:48:29.206Z] 22:48:29     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/browser_test_scroll_thumb_dragging.js | Found a browser window after previous test timed out - 
[task 2022-01-13T22:48:29.206Z] 22:48:29     INFO - GECKO(742) | must wait for focus
[task 2022-01-13T22:48:29.210Z] 22:48:29     INFO - TEST-START | gfx/layers/apz/test/mochitest/browser_test_scrolling_in_extension_popup_window.js
Whiteboard: [stockwell needswork:owner]

Hi Ballo! Can you please take a look at this and maybe you could help us assign this to someone?
Thank you!

Flags: needinfo?(botond)

Forwarding to Hiro as the author of the test.

Flags: needinfo?(botond) → needinfo?(hikezoe.birchill)

Assigning to me. (though I haven't been able to reproduce the failure locally)

Assignee: nobody → hikezoe.birchill
Status: REOPENED → ASSIGNED
Flags: needinfo?(hikezoe.birchill)

I tried some try runs with logging, it turned out there's an unexpected mouse up event so that scrollbar dragging is cancelled by the event. The mouse up event comes from this DispatchMissedButtonReleases call.

:karlt, the DispatchMissedButtonReleases was introduced in bug 544211 to fix an issue on flash, is it still necessary? If it's still necessary, how can we avoid the situation? The test in question here is just doing

  1. open a new browser window
  2. send a mouse move event on a scrollbar thumb in the window
  3. send a mouse down event to the scrollbar thumb
  4. send a mouse move event to move the thumb
  5. send a mouse up event.

Looks like DispatchMissedButtonReleases is called in between 3 and 4 in the failure case.

Flags: needinfo?(karlt)

The synthesized mouse button release would be dispatched because the event state is indicating that the button is not down. Synthesized events implement state only for keyboard state.

However, if the UngrabPointer() method can be removed, then I would hope that DispatchMissedButtonReleases() is no longer needed.

Some state management would be required to cancel setCapture() when a grab or drag steals ownership of pending button release events, but this already exists for at least drags, and more-or-less needed to exist already for sane timing because the timing provided DispatchMissedButtonReleases() was not sane.

Flags: needinfo?(karlt)

Thank you Karl. With your comment now I found what's wrong. Reading carefully one of the log;

Starting drag at 1274, 17 from top-left of #
D/Widget [7fdde05e4c00]: Button 1 press
D/Widget [7fdde05e4c00]: Synthesized button 1 release
D/apz.controller 7fdddfd86800 ending drag
D/apz.controller 7fdddfd86800 changing from state SCROLLBAR_DRAG to NOTHING
D/apz.controller 7fdddfd86800 scroll snapping near (0,0)
D/Widget [7fdde05e4c00]: OnEnterNotify

It shows me that OnEnterNotify gets called after the mouse down event, so that the scroll bar dragging was cancelled unfortunately. It also realized me that on my Linux box, I've been using "Focus on Hover" behavior, thus I can't reproduce the issue locally. I suppose on our CIs, the behavior must be "Click To Focus". I am going to add a click event before start dragging to make sure OnEnterNotify gets called. FWIW, adding await promiseFocus() didn't help.

On Linux if a new browser window received a mouse down event before
OnEnterNotifyEvent gets called, a mouse up event is fired via a
DispatchMissedButtonReleases [1] call in OnEnterNotifyEvent. It cancells
scrollbar dragging trigged by the mouse down event unfortunately. To avoid
this situation we send a click event before start dragging.

[1] https://searchfox.org/mozilla-central/rev/5d2b9e940ca09bd1cbc15aa681f69424cde8904c/widget/gtk/nsWindow.cpp#4181-4184

Thank you, arai and Timothy for the quick review. That said, this is tough. With D136452 the test still fails, so I tried another try run with logging, it turned out that now no mouse up event happened. In the mean time, I did push another try run with an additional mouse move event to make sure the click event happens on the new browser window, it's hard to tell whether it's effective for the "no mouse up event case", but so far the result looks good. So I am going to land with the additional mouse move here.

Pushed by hikezoe.birchill@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a0839052055c
Send a click event on the target window to make sure OnEnterNotifyEvent gets called before start dragging on Linux. r=tnikkel,arai

https://hg.mozilla.org/mozilla-central/rev/a0839052055c

Status: ASSIGNED → RESOLVED
Closed: 3 years ago → 2 years ago
status-firefox98: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 98 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: