Closed Bug 1452820 Opened 2 years ago Closed 1 year ago

Intermittent gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected async key scrolling after test - got false, expected true

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla64
Tracking Status
firefox64 --- fixed

People

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

References

(Depends on 1 open bug)

Details

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

Attachments

(1 file)

Filed by: apavel [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=172764639&repo=mozilla-central

https://queue.taskcluster.net/v1/task/aSalmj2MQKiodinZdZJGXw/runs/0/artifacts/public/logs/live_backing.log

[task 2018-04-09T22:48:04.983Z] 22:48:04     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected no async key scrolling before KEY_Home dispatch 
[task 2018-04-09T22:48:04.984Z] 22:48:04     INFO - Buffered messages logged at 22:48:04
[task 2018-04-09T22:48:04.985Z] 22:48:04     INFO - Reached final scroll position of async KEY_Home scroll
[task 2018-04-09T22:48:04.986Z] 22:48:04     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected at least one paint in compositor test data 
[task 2018-04-09T22:48:04.987Z] 22:48:04     INFO - Buffered messages finished
[task 2018-04-09T22:48:04.988Z] 22:48:04     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected async key scrolling after test - got false, expected true
[task 2018-04-09T22:48:04.988Z] 22:48:04     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:312:5
[task 2018-04-09T22:48:04.989Z] 22:48:04     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:243:45
[task 2018-04-09T22:48:04.990Z] 22:48:04     INFO -     waitForScrollTop/<@gfx/layers/apz/test/mochitest/helper_key_scroll.html:74:9
[task 2018-04-09T22:48:04.990Z] 22:48:04     INFO -     promise callback*waitForApzFlushedRepaints@gfx/layers/apz/test/mochitest/apz_test_utils.js:152:3
[task 2018-04-09T22:48:04.991Z] 22:48:04     INFO -     waitForScrollTop@gfx/layers/apz/test/mochitest/helper_key_scroll.html:73:7
[task 2018-04-09T22:48:04.992Z] 22:48:04     INFO -     EventListener.handleEvent*waitForScrollBottom/<@gfx/layers/apz/test/mochitest/helper_key_scroll.html:60:9
[task 2018-04-09T22:48:04.992Z] 22:48:04     INFO -     promise callback*waitForApzFlushedRepaints@gfx/layers/apz/test/mochitest/apz_test_utils.js:152:3
[task 2018-04-09T22:48:04.993Z] 22:48:04     INFO -     waitForScrollBottom@gfx/layers/apz/test/mochitest/helper_key_scroll.html:56:7
[task 2018-04-09T22:48:06.292Z] 22:48:06     INFO - GECKO(1043) | MEMORY STAT | vsize 1614MB | residentFast 164MB | heapAllocated 21MB
[task 2018-04-09T22:48:06.461Z] 22:48:06     INFO - TEST-OK | gfx/layers/apz/test/mochitest/test_group_keyboard.html | took 6552ms
[task 2018-04-09T22:48:06.503Z] 22:48:06     INFO - GECKO(1043) | ++DOMWINDOW == 16 (0x7effbd83e000) [pid = 1090] [serial = 54] [outer = 0x7effc5c1f000]
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=191971880&repo=mozilla-central&lineNumber=1718

[task 2018-08-03T22:49:40.583Z] 22:49:40     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | Starting subtest helper_key_scroll.html 
[task 2018-08-03T22:49:40.583Z] 22:49:40     INFO - Buffered messages logged at 22:49:39
[task 2018-08-03T22:49:40.584Z] 22:49:40     INFO - must wait for load
[task 2018-08-03T22:49:40.585Z] 22:49:40     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected no async key scrolling before test 
[task 2018-08-03T22:49:40.586Z] 22:49:40     INFO - Reached final scroll position of sync KEY_End scroll
[task 2018-08-03T22:49:40.589Z] 22:49:40     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected no async key scrolling before KEY_Home dispatch 
[task 2018-08-03T22:49:40.589Z] 22:49:40     INFO - Buffered messages logged at 22:49:40
[task 2018-08-03T22:49:40.590Z] 22:49:40     INFO - Reached final scroll position of async KEY_Home scroll
[task 2018-08-03T22:49:40.590Z] 22:49:40     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected at least one paint in compositor test data 
[task 2018-08-03T22:49:40.591Z] 22:49:40     INFO - Buffered messages finished
[task 2018-08-03T22:49:40.592Z] 22:49:40     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected async key scrolling after test - got false, expected true
[task 2018-08-03T22:49:40.592Z] 22:49:40     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:312:5
[task 2018-08-03T22:49:40.593Z] 22:49:40     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:256:45
[task 2018-08-03T22:49:40.593Z] 22:49:40     INFO -     waitForScrollTop/<@gfx/layers/apz/test/mochitest/helper_key_scroll.html:74:9
[task 2018-08-03T22:49:40.593Z] 22:49:40     INFO -     setTimeout handler*paintListener@SimpleTest/paint_listener.js:32:7
[task 2018-08-03T22:49:40.594Z] 22:49:40     INFO -     EventListener.handleEvent*@SimpleTest/paint_listener.js:35:3
[task 2018-08-03T22:49:40.594Z] 22:49:40     INFO -     @SimpleTest/paint_listener.js:1:2
[task 2018-08-03T22:49:42.327Z] 22:49:42     INFO - GECKO(1015) | MEMORY STAT | vsize 471MB | residentFast 187MB | heapAllocated 17MB
[task 2018-08-03T22:49:42.490Z] 22:49:42     INFO - TEST-OK | gfx/layers/apz/test/mochitest/test_group_keyboard.html | took 4518ms
[task 2018-08-03T22:49:42.528Z] 22:49:42     INFO - GECKO(1015) | ++DOMWINDOW == 19 (0xe6d34800) [pid = 1070] [serial = 71] [outer = 0xe9173280]
[task 2018-08-03T22:49:42.566Z] 22:49:42     INFO - TEST-START | gfx/layers/apz/test/mochitest/test_group_mouseevents.html
[task 2018-08-03T22:49:42.666Z] 22:49:42     INFO - GECKO(1015) | --DOMWINDOW == 18 (0xe6d35400) [pid = 1070] [serial = 61] [outer = (nil)] [url = about:blank]
[task 2018-08-03T22:49:42.666Z] 22:49:42     INFO - GECKO(1015) | --DOMWINDOW == 17 (0xe6d34000) [pid = 1070] [serial = 62] [outer = (nil)] [url = about:blank]
[task 2018-08-03T22:49:42.667Z] 22:49:42     INFO - GECKO(1015) | --DOMWINDOW == 16 (0xe7ad0000) [pid = 1070] [serial = 59] [outer = (nil)] [url = about:blank]
[task 2018-08-03T22:49:42.670Z] 22:49:42     INFO - GECKO(1015) | --DOMWINDOW == 15 (0xe7ad7c00) [pid = 1070] [serial = 56] [outer = (nil)] [url = about:blank]
[task 2018-08-03T22:49:42.671Z] 22:49:42     INFO - GECKO(1015) | --DOMWINDOW == 14 (0xe6d31400) [pid = 1070] [serial = 64] [outer = (nil)] [url = about:blank]
[task 2018-08-03T22:49:42.695Z] 22:49:42     INFO - GECKO(1015) | ++DOMWINDOW == 15 (0xe6d2e400) [pid = 1070] [serial = 72] [outer = 0xe9173280]
[task 2018-08-03T22:49:42.813Z] 22:49:42     INFO - GECKO(1015) | ++DOCSHELL 0xe6d36800 == 6 [pid = 1070] [id = {f8ba916e-de9a-4ebd-a273-7ccc1ee90fb8}]
[task 2018-08-03T22:49:42.814Z] 22:49:42     INFO - GECKO(1015) | ++DOMWINDOW == 16 (0xe80deca0) [pid = 1070] [serial = 73] [outer = (nil)]
[task 2018-08-03T22:49:42.902Z] 22:49:42     INFO - GECKO(1015) | ++DOMWINDOW == 17 (0xe6d38400) [pid = 1070] [serial = 74] [outer = 0xe80deca0]
[task 2018-08-03T22:49:43.164Z] 22:49:43     INFO - GECKO(1015) | ++DOMWINDOW == 18 (0xe7ad7400) [pid = 1070] [serial = 75] [outer = 0xe80deca0]
[task 2018-08-03T22:49:43.787Z] 22:49:43     INFO - GECKO(1015) | Parent process: flushed APZ repaints, waiting for callback...
[task 2018-08-03T22:49:43.873Z] 22:49:43     INFO - GECKO(1015) | Flushed APZ repaints, waiting for callback...
[task 2018-08-03T22:49:44.051Z] 22:49:44     INFO - GECKO(1015) | ++DOCSHELL 0xe7ad0000 == 7 [pid = 1070] [id = {d498bb52-05e3-4d4b-ae32-81346d2d7b0c}]
[task 2018-08-03T22:49:44.052Z] 22:49:44     INFO - GECKO(1015) | ++DOMWINDOW == 19 (0xe80e2a60) [pid = 1070] [serial = 76] [outer = (nil)]
[task 2018-08-03T22:49:44.053Z] 22:49:44     INFO - GECKO(1015) | Finished synthesizing click, waiting for button to be clicked...
[task 2018-08-03T22:49:44.318Z] 22:49:44     INFO - GECKO(1015) | ++DOMWINDOW == 20 (0xe6d2f000) [pid = 1070] [serial = 77] [outer = 0xe80e2a60]
[task 2018-08-03T22:49:44.536Z] 22:49:44     INFO - GECKO(1015) | ++DOMWINDOW == 21 (0xe7ada000) [pid = 1070] [serial = 78] [outer = 0xe80e2a60]
[task 2018-08-03T22:49:44.857Z] 22:49:44     INFO - GECKO(1015) | JavaScript error: resource:///modules/ClickEventHandler.jsm, line 129: TypeError: content is null
[task 2018-08-03T22:49:44.858Z] 22:49:44     INFO - GECKO(1015) | [Child 1070, Main Thread] WARNING: PuppetWidget without Tab does not have chrome information.: file /builds/worker/workspace/build/src/widget/PuppetWidget.cpp, line 1258
[task 2018-08-03T22:49:45.138Z] 22:49:45     INFO - GECKO(1015) | Parent process: flushed APZ repaints, waiting for callback...
[task 2018-08-03T22:49:45.234Z] 22:49:45     INFO - GECKO(1015) | Flushed APZ repaints, waiting for callback...
[task 2018-08-03T22:49:45.316Z] 22:49:45     INFO - GECKO(1015) | Flushed APZ repaints, waiting for callback...
[task 2018-08-03T22:49:45.619Z] 22:49:45     INFO - GECKO(1015) | ++DOCSHELL 0xe7ad3c00 == 8 [pid = 1070] [id = {ac8bc666-06c0-4002-8ec1-9802d0106a82}]
[task 2018-08-03T22:49:45.621Z] 22:49:45     INFO - GECKO(1015) | ++DOMWINDOW == 22 (0xe80deb80) [pid = 1070] [serial = 79] [outer = (nil)]
[task 2018-08-03T22:49:45.629Z] 22:49:45     INFO - GECKO(1015) | Finished synthesizing click, waiting for button to be clicked...
[task 2018-08-03T22:49:45.928Z] 22:49:45     INFO - GECKO(1015) | ++DOMWINDOW == 23 (0xe6d32400) [pid = 1070] [serial = 80] [outer = 0xe80deb80]
[task 2018-08-03T22:49:46.099Z] 22:49:46     INFO - GECKO(1015) | ++DOMWINDOW == 24 (0xe7add000) [pid = 1070] [serial = 81] [outer = 0xe80deb80]
[task 2018-08-03T22:49:46.155Z] 22:49:46     INFO - GECKO(1015) | --DOCSHELL 0xe6d38000 == 7 [pid = 1070] [id = {c2bbf9a2-2cb6-42c4-909a-4f7f366cb316}]
[task 2018-08-03T22:49:46.157Z] 22:49:46     INFO - GECKO(1015) | --DOCSHELL 0xe6d30400 == 6 [pid = 1070] [id = {8969b4da-052b-4d74-ab4c-a3bca53e29c7}]
[task 2018-08-03T22:49:46.158Z] 22:49:46     INFO - GECKO(1015) | --DOMWINDOW == 23 (0xe80e2160) [pid = 1070] [serial = 63] [outer = (nil)] [url = http://mochi.test:8888/tests/gfx/layers/apz/test/mochitest/helper_hittest_nested_transforms_bug1459696.html]
[task 2018-08-03T22:49:46.359Z] 22:49:46     INFO - GECKO(1015) | JavaScript error: resource:///modules/ClickEventHandler.jsm, line 129: TypeError: content is null
[task 2018-08-03T22:49:46.359Z] 22:49:46     INFO - GECKO(1015) | [Child 1070, Main Thread] WARNING: PuppetWidget without Tab does not have chrome information.: file /builds/worker/workspace/build/src/widget/PuppetWidget.cpp, line 1258
[task 2018-08-03T22:49:46.617Z] 22:49:46     INFO - GECKO(1015) | Parent process: flushed APZ repaints, waiting for callback...
[task 2018-08-03T22:49:46.700Z] 22:49:46     INFO - GECKO(1015) | Flushed APZ repaints, waiting for callback...
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
This bug has failed 45 times in the last 7 days. It mostly fails on Linux platforms, with a few failures on windows and osx. It affects debug, asan, pto and pgo build types.

Log:
https://treeherder.mozilla.org/logviewer.html#?job_id=203588018&repo=mozilla-inbound&lineNumber=6182

INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected at least one paint in compositor test data 
[task 2018-10-05T08:16:12.843Z] 08:16:12     INFO - Buffered messages finished
[task 2018-10-05T08:16:12.844Z] 08:16:12     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected async key scrolling after test - got false, expected true
[task 2018-10-05T08:16:12.845Z] 08:16:12     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:312:5
[task 2018-10-05T08:16:12.845Z] 08:16:12     INFO -     spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:265:45
[task 2018-10-05T08:16:12.846Z] 08:16:12     INFO -     waitForScrollTop/<@gfx/layers/apz/test/mochitest/helper_key_scroll.html:74:9
[task 2018-10-05T08:16:12.847Z] 08:16:12     INFO -     setTimeout handler*paintListener@SimpleTest/paint_listener.js:32:7
[task 2018-10-05T08:16:12.847Z] 08:16:12     INFO -     EventListener.handleEvent*@SimpleTest/paint_listener.js:35:3
[task 2018-10-05T08:16:12.848Z] 08:16:12     INFO -     @SimpleTest/paint_listener.js:1:2
[task 2018-10-05T08:16:15.554Z] 08:16:15     INFO - GECKO(6589) | MEMORY STAT | vsize 1508MB | residentFast 173MB | heapAllocated 24MB
[task 2018-10-05T08:16:15.597Z] 08:16:15     INFO - TEST-OK | gfx/layers/apz/test/mochitest/test_group_keyboard.html | took 3658ms
[task 2018-10-05T08:16:15.623Z] 08:16:15     INFO - TEST-START | gfx/layers/apz/test/mochitest/test_group_mouseevents.html

kats: Can you please take a look at this bug?
Flags: needinfo?(kats)
QA Contact: kats
Whiteboard: [stockwell needswork]
The frequency went up shortly after bug 1495055 landed, so I expect the backout of that bug to fix this.
Blocks: 1495055
Flags: needinfo?(kats)
QA Contact: kats
The underlying issue here seems to be that the test is querying "window.scrollYMax", which is a property that doesn't exist (the intended property is named "scrollMaxY" [2]). As a result, the test doesn't wait until the page is scrolled to the bottom, as it intends.

The test nevertheless passes most of the time, since usually by the time any scroll event is dispatched, keyboard scrolling has occurred, but this is not guaranteed. Bug 1495055 likely just changed timings so as to make this failure more frequent.

[1] https://searchfox.org/mozilla-central/rev/807a37c670c093b6e5201841a7c5315ba67ba8d5/gfx/layers/apz/test/mochitest/helper_key_scroll.html#39
[2] https://developer.mozilla.org/en-US/docs/Web/API/Window/scrollMaxY
Assignee: nobody → botond
Pushed by bballo@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/75b958f179a8
Use correct window property for testing end of scroll range. r=rhunt
https://hg.mozilla.org/mozilla-central/rev/75b958f179a8
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
Depends on: 1497011
You need to log in before you can comment on or make changes to this bug.