Closed Bug 1118268 Opened 5 years ago Closed 4 years ago

Intermittent testPrivateBrowsing | GeckoEventExpecter - blockForEvent timeout: Tab:Added

Categories

(Firefox for Android :: General, defect)

ARM
Android
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 48
Tracking Status
firefox48 --- fixed

People

(Reporter: RyanVM, Assigned: gbrown)

References

Details

(Keywords: intermittent-failure)

Attachments

(6 files)

Attached file test log
See the attached log.
Attached image test screenshot
The test selects "New Private Tab" from the menu and then waits for Tab:Added, but the recent screenshots here show that the menu is still displayed...a timing issue when making the menu selection? Maybe that item is not yet clickable??

mcomella -- Any interest? Or can you find an owner for this bug?
Flags: needinfo?(michael.l.comella)
No failures in 3 weeks - maybe no need for follow-up?
Flags: needinfo?(michael.l.comella)
All recent failures have screenshots showing the menu (with New Private Tab enabled) displayed when the Tab:Added timeout occurs (as though the menu selection is not working).
2:39:56     INFO -  TEST-START | testPrivateBrowsing
22:39:56     INFO -  TEST-PASS | testPrivateBrowsing | Robocop tests need the test device screen to be powered on. -
22:39:56     INFO -  TEST-PASS | testPrivateBrowsing | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
22:39:56     INFO -  EventExpecter: no longer listening for Gecko:Ready
22:39:56     INFO -  TEST-PASS | testPrivateBrowsing | waiting for urlbar text to gain focus - urlbar text gained focus
22:39:56     INFO -  TEST-PASS | testPrivateBrowsing | URL typed properly - about:blank should equal about:blank
22:39:56     INFO -  TEST-PASS | testPrivateBrowsing | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded
22:39:56     INFO -  EventExpecter: no longer listening for DOMContentLoaded
22:39:56     INFO -  Dumping ALL the threads!
22:39:56     INFO -  Thread[Instr: org.mozilla.gecko.FennecInstrumentationTestRunner,5,main]
22:39:56     INFO -  dalvik.system.VMStack.getThreadStackTrace(Native Method)
22:39:56     INFO -  java.lang.Thread.getStackTrace(Thread.java:579)
22:39:56     INFO -  java.lang.Thread.getAllStackTraces(Thread.java:521)
22:39:56     INFO -  org.mozilla.gecko.FennecNativeDriver.logAllStackTraces(FennecNativeDriver.java:317)
22:39:56     INFO -  org.mozilla.gecko.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:95)
22:39:56     INFO -  org.mozilla.gecko.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:80)
22:39:56     INFO -  org.mozilla.gecko.tests.PixelTest.addTab(PixelTest.java:63)
22:39:56     INFO -  org.mozilla.gecko.tests.testPrivateBrowsing.addTab(testPrivateBrowsing.java:19)
22:39:56     INFO -  org.mozilla.gecko.tests.testPrivateBrowsing.testPrivateBrowsing(testPrivateBrowsing.java:30)
22:39:56     INFO -  java.lang.reflect.Method.invokeNative(Native Method)
22:39:56     INFO -  java.lang.reflect.Method.invoke(Method.java:525)
22:39:56     INFO -  android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:214)
22:39:56     INFO -  android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:199)
(In reply to Geoff Brown [:gbrown] from comment #50)
> All recent failures have screenshots showing the menu (with New Private Tab
> enabled) displayed when the Tab:Added timeout occurs (as though the menu
> selection is not working).

I investigated and found that the MotionEvent generated by robotium to click on the "New Private Tab" menu item can be observed by adding an onInterceptTouchEvent() handler to GeckoMenu, even when the test fails and the robocop screenshot shows the menu it still displayed. However, in the failure cases, onClick is not triggered: It looks like the click gets to GeckoMenu but is discarded. I have not been able to observe any GeckoMenu state differences that might account for the failure.

However, while comparing logcats, I noticed that failures were strongly correlated with log messages associated with Gecko:DelayedStartup, like: http://hg.mozilla.org/mozilla-central/annotate/9a8f2342fb31/mobile/android/base/BrowserApp.java#l1762. If the "New Private Tab" click is being processed by GeckoMenu around the time that Gecko:DelayedStartup is being processed, the click is often discarded.

Waiting for delayed startup before starting the test appears to eliminate the failure:

(base/no changes) https://treeherder.mozilla.org/#/jobs?repo=try&revision=e2c4d5620d41
(wait for delayed startup) https://treeherder.mozilla.org/#/jobs?repo=try&revision=766cdc3c4c8b

I would like to see the root cause of the failure determined and addressed, but I cannot find the missing connection between Gecko:DelayedStartup and this apparent fault in GeckoMenu. It looks like neither GeckoMenu nor testPrivateBrowsing are strongly owned. margaret -- Can you suggest a way forward?
Flags: needinfo?(margaret.leibovic)
See Also: → 1059281
(In reply to Geoff Brown [:gbrown] from comment #54)

> I would like to see the root cause of the failure determined and addressed,
> but I cannot find the missing connection between Gecko:DelayedStartup and
> this apparent fault in GeckoMenu. It looks like neither GeckoMenu nor
> testPrivateBrowsing are strongly owned. margaret -- Can you suggest a way
> forward?

I know that mcomella has recently been looking at GeckoMenu code, so he may have some insights.

Looking into this myself, I don't see any connection between Gecko:DelayedStartup and a problem with GeckoMenu. One thought I had is that some menu items are disabled until Gecko is up and running (e.g. Settings), so maybe something is happening where updating the menu is causing the clicks to fail, although that happens on "Gecko:Ready":
http://hg.mozilla.org/mozilla-central/annotate/67a788db9f07/mobile/android/base/BrowserApp.java#l1796

Sorry I can't be more helpful :(
Flags: needinfo?(margaret.leibovic) → needinfo?(michael.l.comella)
This could be related to bug 1217484 comment 8. The solution appears to be waiting for the animations to finish before clicking on the next thing.
See Also: → 1217484
tracking-fennec: --- → ?
Actually, I'll just try taking a look at this.
Assignee: nobody → margaret.leibovic
tracking-fennec: ? → ---
Assignee: margaret.leibovic → michael.l.comella
Flags: needinfo?(michael.l.comella)
testPrivateBrowsing selects menu items to open a new tab and I suspect the
failures occur because we don't wait for the animations to finish before
attempting to click again, like in bug 1217484 comment 8.

Review commit: https://reviewboard.mozilla.org/r/32825/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/32825/
Attachment #8713795 - Flags: review?(margaret.leibovic)
(In reply to Michael Comella (:mcomella) from comment #73)
> Created attachment 8713795 [details]
> MozReview Request: Bug 1118268 - Wait for animations to finish when
> selecting menu items. r=margaret
> 
> testPrivateBrowsing selects menu items to open a new tab and I suspect the
> failures occur because we don't wait for the animations to finish before
> attempting to click again, like in bug 1217484 comment 8.

Wait -- are we not disabling animations on our test devices?  This is explicitly recommended at http://developer.android.com/training/testing/ui-testing/espresso-testing.html.

gbrown: can you confirm or deny and file to get this done ASAP?
Flags: needinfo?(gbrown)
Attached image 4.3 emulator settings
Animations are disabled on the 4.3 emulator.
Flags: needinfo?(gbrown)
Attached image 2.3 emulator settings
On 2.3, I believe I was unable to find animation settings. (There are no Developer Options.)
(In reply to Geoff Brown [:gbrown] from comment #76)
> On 2.3, I believe I was unable to find animation settings. (There are no
> Developer Options.)

It's in Settings -> Applications -> Development
Flags: needinfo?(gbrown)
Thanks, but there's no animation-related settings there. Just "USB Debugging", "Stay awake", and "Allow mock locations".
Flags: needinfo?(gbrown)
I'm not sure why my try push didn't run 4.3 tests but it passed ~10x on 2.3 – I'd say we should try landing it!
Maybe s/android-api-11/android-api-15/ ?
(In reply to Geoff Brown [:gbrown] from comment #80)
> Maybe s/android-api-11/android-api-15/ ?

Pushed to try via reviewboard w/ api-15.
I got two failures with my change, the stack is:

11:43:57     INFO -  org.mozilla.gecko.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:80)
11:43:57     INFO -  org.mozilla.gecko.tests.PixelTest.addTab(PixelTest.java:64)
11:43:57     INFO -  org.mozilla.gecko.tests.testPrivateBrowsing.addTab(testPrivateBrowsing.java:19)

Which is the DOMContentLoaded event expecter. There's no screenshot so it's hard to say which state we're getting stuck in (e.g. opening the menu, clicking the new tab button, or waiting for content to load).

Geoff, do you know why there is sometimes a screenshot and sometimes not?
Flags: needinfo?(gbrown)
No, I don't know. 

The screenshot is requested at http://hg.mozilla.org/mozilla-central/annotate/d07dbd40dcd2/mobile/android/tests/browser/robocop/src/org/mozilla/gecko/tests/BaseRobocopTest.java#l192 -- which should have been hit in this case.
Flags: needinfo?(gbrown)
Without a screenshot (btw, filed bug 1244906 to find out why they're missing), I'm going to shoot this one back to Margaret – I have other things to focus on.
Assignee: michael.l.comella → margaret.leibovic
https://treeherder.mozilla.org/#/jobs?repo=try&revision=bfdc25bcc6ad reproduces this failure with mcomella's patch (not listed on the treeherder push, but it *is* there) and screenshots. I used an experimental technique to get a screenshot of the host when the test has not produced any output for 120 seconds. Screenshots are uploaded as artifacts named 'mozilla-test-fail-screenshot...'. For example:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/3e27f60d8865c9b3c8da50e31749593d527103b53327ffbe3f002ea2eb2ef18a7315d0f317b5b95979aae6bd3f2b854a75132790fe4affe00394f149d0bf34e4

shows about:blank in the url bar and the menu open.
So we have an issue finding/clicking on the menu item. Looking at UITest's AppMenuComponent.findAppMenuItemView (which I also think only works some of the time), we seem to have a more robust mechanism where we search through all the views for the specific view types our menu items can be and click those – maybe we should use AppMenuComponent directly or (less preferably) steal that algorithm for BaseTest.

We could also add logging to BaseTest.selectMenuItem.
I don't think the problem is in UITest: recall comment 54.
s/UITest/BaseTest/any of the test code/
Oops, I missed comment 54 (best ignore my work then :\ – I was just trying to fix the failure).

Jim, can you take a look at comment 54 and let us know if you have any ideas what might be up?
Flags: needinfo?(nchen)
Sorry I'm not familiar with GeckoMenu or how it relates to Gecko:DelayedStartup.
Flags: needinfo?(nchen)
A speculative improvement: If the cause of this failure is that GeckoMenu is not receiving the click sent by robotium, maybe there is a timing issue in robocop's menu item selection. Is robocop clicking on the item before the onClick handler is ready? Before the item is enabled?

This has 3 changes in selectMenuItem():
 - open the menu with view clicks rather than simulating the Menu key
 - remove old, unused More/Tools support (Tools items can still be accessed with selectMenuItemByPath)
 - waitForEnabledText instead of waitForText

Encouraging try results: https://treeherder.mozilla.org/#/jobs?repo=try&revision=94c4b14c7143
Attachment #8734742 - Flags: review?(margaret.leibovic)
Comment on attachment 8734742 [details] [diff] [review]
improve menu item selection

Review of attachment 8734742 [details] [diff] [review]:
-----------------------------------------------------------------

Nice, this looks reasonable to me.
Attachment #8734742 - Flags: review?(margaret.leibovic) → review+
Assignee: margaret.leibovic → gbrown
https://hg.mozilla.org/mozilla-central/rev/926f349435b2
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 48
You need to log in before you can comment on or make changes to this bug.