Closed Bug 1519580 Opened 5 years ago Closed 3 years ago

Intermittent mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | Test timed out.

Categories

(Firefox for Android Graveyard :: Testing, defect, P5)

All
Android
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

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

Attachments

(1 file)

Filed by: aiakab [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=221407772&repo=autoland

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

'[task 2019-01-11T23:46:55.779Z] 23:46:55 INFO - 122 INFO TEST-START | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html
[task 2019-01-11T23:51:50.078Z] 23:51:50 INFO - Buffered messages logged at 23:46:49
[task 2019-01-11T23:51:50.080Z] 23:51:50 INFO - 123 INFO AddTask.js | Entering test test_sessionStoreScrollPositionVisualViewport
[task 2019-01-11T23:51:50.080Z] 23:51:50 INFO - 124 INFO Now waiting for pageshow event from browser
[task 2019-01-11T23:51:50.081Z] 23:51:50 INFO - Buffered messages logged at 23:46:54
[task 2019-01-11T23:51:50.081Z] 23:51:50 INFO - 125 INFO Received event pageshow from browser
[task 2019-01-11T23:51:50.081Z] 23:51:50 INFO - 126 INFO Now waiting for SSTabScrollCaptured event from container
[task 2019-01-11T23:51:50.081Z] 23:51:50 INFO - Buffered messages logged at 23:46:58
[task 2019-01-11T23:51:50.082Z] 23:51:50 INFO - 127 INFO Received event SSTabScrollCaptured from container
[task 2019-01-11T23:51:50.082Z] 23:51:50 INFO - 128 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | scrollX set correctly
[task 2019-01-11T23:51:50.082Z] 23:51:50 INFO - 129 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | scrollY set correctly
[task 2019-01-11T23:51:50.082Z] 23:51:50 INFO - 130 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | zoom set correctly
[task 2019-01-11T23:51:50.083Z] 23:51:50 INFO - 131 INFO Now waiting for SSTabScrollCaptured event from container
[task 2019-01-11T23:51:50.084Z] 23:51:50 INFO - 132 INFO Now waiting for APZ:TransformEnd notification from Gecko
[task 2019-01-11T23:51:50.084Z] 23:51:50 INFO - Buffered messages logged at 23:47:00
[task 2019-01-11T23:51:50.085Z] 23:51:50 INFO - 133 INFO Received event SSTabScrollCaptured from container
[task 2019-01-11T23:51:50.086Z] 23:51:50 INFO - 134 INFO Received APZ:TransformEnd notification from Gecko
[task 2019-01-11T23:51:50.087Z] 23:51:50 INFO - Buffered messages logged at 23:47:01
[task 2019-01-11T23:51:50.088Z] 23:51:50 INFO - 135 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | we should be scrolled to the right
[task 2019-01-11T23:51:50.089Z] 23:51:50 INFO - 136 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | we scrolled horizontally
[task 2019-01-11T23:51:50.089Z] 23:51:50 INFO - 137 INFO Now waiting for pageshow event from browser
[task 2019-01-11T23:51:50.090Z] 23:51:50 INFO - Buffered messages logged at 23:47:03
[task 2019-01-11T23:51:50.091Z] 23:51:50 INFO - 138 INFO Received event pageshow from browser
[task 2019-01-11T23:51:50.091Z] 23:51:50 INFO - 139 INFO Now waiting for SSTabScrollCaptured event from container
[task 2019-01-11T23:51:50.092Z] 23:51:50 INFO - Buffered messages logged at 23:47:05
[task 2019-01-11T23:51:50.093Z] 23:51:50 INFO - 140 INFO Received event SSTabScrollCaptured from container
[task 2019-01-11T23:51:50.093Z] 23:51:50 INFO - 141 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | scrollX set correctly
[task 2019-01-11T23:51:50.094Z] 23:51:50 INFO - 142 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | scrollY set correctly
[task 2019-01-11T23:51:50.095Z] 23:51:50 INFO - 143 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | zoom set correctly
[task 2019-01-11T23:51:50.095Z] 23:51:50 INFO - 144 INFO Now waiting for SSTabScrollCaptured event from container
[task 2019-01-11T23:51:50.096Z] 23:51:50 INFO - 145 INFO Now waiting for APZ:TransformEnd notification from Gecko
[task 2019-01-11T23:51:50.097Z] 23:51:50 INFO - Buffered messages logged at 23:47:06
[task 2019-01-11T23:51:50.097Z] 23:51:50 INFO - 146 INFO Received APZ:TransformEnd notification from Gecko
[task 2019-01-11T23:51:50.098Z] 23:51:50 INFO - Buffered messages finished
[task 2019-01-11T23:51:50.099Z] 23:51:50 INFO - 147 INFO TEST-UNEXPECTED-FAIL | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | Test timed out.
[task 2019-01-11T23:51:50.100Z] 23:51:50 INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:275:7
[task 2019-01-11T23:51:50.100Z] 23:51:50 INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:121:7
[task 2019-01-11T23:51:50.101Z] 23:51:50 INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:142:7
[task 2019-01-11T23:52:00.301Z] 23:52:00 INFO - 148 INFO TEST-OK | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | took 302991ms'

I'd need to look into this, respectively try to reproduce this on Try (or an emulator) with more debug logging [1] to make sure it's not some other obscure issue, but I wonder whether this is the same issue that caused the assertion in bug 1500565?
I.e. we're inputting simulated touch events too rapidly and as a result the attempted fling stalls and we don't scroll at all. This still happens often enough locally on a real phone, so maybe once in a while it could happen even on the emulator, slow as it is?

The test log says

  1. Run each test 10 times in one browser. : Pass
  2. Run each test 5 times in a new browser each time. : FAIL
  3. Run each test 10 times in one browser, in chaos mode. : not run / incomplete
  4. Run each test 5 times in a new browser each time, in chaos mode. : not run / incomplete

so the failures aren't due to chaos mode.

[1] See https://treeherder.mozilla.org/#/jobs?repo=try&revision=bfe36b310edb784c5cd12766e7c316f54f80692a.

(In reply to Jan Henning [:JanH] from comment #1)

I'd need to look into this, respectively try to reproduce this on Try (or an emulator) with more debug logging [1] to make sure it's not some other obscure issue, but I wonder whether this is the same issue that caused the assertion in bug 1500565?
I.e. we're inputting simulated touch events too rapidly and as a result the attempted fling stalls and we don't scroll at all. This still happens often enough locally on a real phone, so maybe once in a while it could happen even on the emulator, slow as it is?

A touch gesture generated by synthesizeNativeTouchSequences() can cause scrolling in two ways:

  • Panning, which happens directly in response to the touch-move events
  • A fling animation, which starts in response to the touch-end and represents momentum scrolling

The issue in bug 1500565 only affected the fling, not the pan. Presumably, this test is relying on the touch gesture to perform the pan, which should be unaffected by timestamps. That is, even if the fling doesn't occur due to the timestamps, the pan should still cause scrolling.

See Also: → 1520840

In the last 7 days, there have been 31 failures.
The failures are on android-em-4-3-armv7-api16-pgo platform, opt build type

An example of a recent log file:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=235317039&repo=autoland&lineNumber=1960

And the relevant part of the log:
task 2019-03-22T01:19:44.498Z] 01:19:44 INFO - 99 INFO TEST-PASS | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | zoom set correctly
[task 2019-03-22T01:19:44.498Z] 01:19:44 INFO - 100 INFO Now waiting for SSTabScrollCaptured event from container
[task 2019-03-22T01:19:44.498Z] 01:19:44 INFO - 101 INFO Now waiting for APZ:TransformEnd notification from Gecko
[task 2019-03-22T01:19:44.499Z] 01:19:44 INFO - Buffered messages logged at 01:14:45
[task 2019-03-22T01:19:44.500Z] 01:19:44 INFO - 102 INFO Received APZ:TransformEnd notification from Gecko
[task 2019-03-22T01:19:44.500Z] 01:19:44 INFO - Buffered messages finished
[task 2019-03-22T01:19:44.501Z] 01:19:44 INFO - 103 INFO TEST-UNEXPECTED-FAIL | mobile/android/tests/browser/chrome/test_session_scroll_visual_viewport.html | Test timed out.
[task 2019-03-22T01:19:44.501Z] 01:19:44 INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:275:18
[task 2019-03-22T01:19:44.502Z] 01:19:44 INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:121:22
[task 2019-03-22T01:19:44.502Z] 01:19:44 INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:142:7

:Geoff As you are the triage owner of this component, could you please take a look at this?
Thank you!

Flags: needinfo?(gbrown)
Whiteboard: [stockwell needswork:owner]

It looks like failures became more frequent when we turned on Android pgo builds.

JanH - Can you have another look? Skipping the test on android && !debug would avoid almost all failures, if you want to go that route.

Flags: needinfo?(gbrown) → needinfo?(jh+bugzilla)

I still think that the underlying problem is some issue with synthesizeNativeTouchSequences that gets more frequent the faster the test device is (so PGO builds failing more frequently would make sense if they improved our performance), because that is where the test is failing - we've executed the scroll gesture and got the APZ:TransformEnd notification, but no scroll event. (Or sometimes we do get a scroll event, but haven't actually scrolled, as in bug 1520840 - possibly we only managed to do a sub-pixel scroll that rounds down to 0 CSS px in that case?)

I guess running the tests only on debug should be okay as a stopgap, though...

Flags: needinfo?(jh+bugzilla)
OS: Unspecified → Android
Hardware: Unspecified → All

Without having examined the code, is it possible that APZCCallbackHelper is now doing a visual scroll and not triggering an invalidation/repaint? If so that might explain why the promiseApzRepaintsFlushed stuff is returning even though the new scroll position hasn't necessarily propagated everywhere.

The test doesn't just rely on the APZ flushing logic, though - via the session store it also waits for a (visual!) scroll event to occur, and those timeouts seem to indicate we never even got a scroll event in that case.

My suggestion for how to debug this would be:

  • do a local x86 Android build with added logging
  • run the mochitest in the emulator with --repeat 100 --run-until-failure
  • examine logs from failing run
  • repeat with more logging added as necessary

Skip mochitest-chrome test failing frequently on android/pgo. This directory of tests
only runs on Android 4.3, so the manifest annotation is simple.

Discussed in bug; see comment 17.

Keywords: leave-open
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/10315d09278b
Skip test_session_scroll_visual_viewport.html on android/pgo; r=jmaher
Keywords: test-disabled
Whiteboard: [stockwell needswork:owner] → [stockwell disabled]

Same failure continues on /debug, infrequently.

Priority: -- → P5
We have completed our launch of our new Firefox on Android. The development of the new versions use GitHub for issue tracking. If the bug report still reproduces in a current version of [Firefox on Android nightly](https://play.google.com/store/apps/details?id=org.mozilla.fenix) an issue can be reported at the [Fenix GitHub project](https://github.com/mozilla-mobile/fenix/). If you want to discuss your report please use [Mozilla's chat](https://wiki.mozilla.org/Matrix#Connect_to_Matrix) server https://chat.mozilla.org and join the [#fenix](https://chat.mozilla.org/#/room/#fenix:mozilla.org) channel.
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: