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]

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...

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?

The frequency went up shortly after bug 1495055 landed, so I expect the backout of that bug to fix this.

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

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