Closed Bug 1114655 Opened 10 years ago Closed 10 years ago

Intermittent testAppMenuPathways | Waiting for legacy "More" menu to open.

Categories

(Firefox for Android Graveyard :: General, defect)

Product:
Firefox for Android Graveyard
Component:
General
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox35 fixed, firefox36 fixed, firefox37 fixed, firefox-esr31 unaffected)

Status:
RESOLVED FIXED
Milestone:
Firefox 37
Tracking Flags:
Tracking Status
firefox35 --- fixed
firefox36 --- fixed
firefox37 --- fixed
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: gbrown)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

increase WaitHelper default max time from 5000 ms to 15000 ms
1.17 KB, patch
mcomella
: review+
Details | Diff | Splinter Review
Definitely from bug 1085837. 09:25:07 INFO - SimpleTest START 09:25:07 INFO - TEST-START | testAppMenuPathways 09:25:07 INFO - TEST-PASS | testAppMenuPathways | Robocop tests need the test device screen to be powered on. - 09:25:07 INFO - TEST-PASS | testAppMenuPathways | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready 09:25:07 INFO - EventExpecter: no longer listening for Gecko:Ready 09:25:07 INFO - TEST-PASS | testAppMenuPathways | Menu is not open - 09:25:07 INFO - TEST-PASS | testAppMenuPathways | Waiting for menu to open. - 09:25:07 INFO - TEST-PASS | testAppMenuPathways | The base menu is already open - 09:25:07 WARNING - TEST-UNEXPECTED-FAIL | testAppMenuPathways | Waiting for legacy "More" menu to open. - 09:25:07 INFO - TEST-OK | testAppMenuPathways | took 54533ms 09:25:07 INFO - TEST-START | Shutdown 09:25:07 INFO - Passed: 5 09:25:07 INFO - Failed: 1 09:25:07 INFO - Todo: 0 09:25:07 INFO - SimpleTest FINISHED
Related to bug 1113427? Probably not, because it's the first time the more menu is opened.
We are waiting for the "More" menu to open by waiting for R.string.share (which should be "Share")...and all the screenshots here show the More menu open with "Share" as the top item. It looks like "Share" is disabled -- could that be an issue?
See Also: → 1113754
See Also: 1113754 →
See Also: → 1114658
(In reply to Geoff Brown [:gbrown] from comment #25) > It looks like "Share" is disabled -- > could that be an issue? From what I can see, the menu item being disabled shouldn't affect the test. But I'm no expert.
Some attempts at debugging: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a710e3c1068f https://treeherder.mozilla.org/#/jobs?repo=try&revision=71e005ab2ff2 Consider the one failure: http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/fd9847d9bfa1f73a4595152c8515b0f3742f4188831d7ef20792d621472da7814deeb73d4f1eda732cb5d7a931608966bdefa255b232b96070a5444bad1728b5 It took over 5000 ms to execute isLegacyMoreMenuOpen just once. 12-29 20:20:38.822 I/Robocop ( 1344): {"message":"","time":1419913238815,"source":"robocop","status":"PASS","test":"testAppMenuPathways","thread":null,"subtest":"isLegacyMoreMenuOpen called","action":"test_status","pid":null} 12-29 20:20:43.923 I/Robocop ( 1344): {"message":"","time":1419913243909,"source":"robocop","status":"PASS","test":"testAppMenuPathways","thread":null,"subtest":"isLegacyMoreMenuOpen: no Share","action":"test_status","pid":null} So the waitFor (using WaitHelper default of 5000 ms) fails immediately, without checking isLegacyMoreMenuOpen again: 12-29 20:20:45.012 I/Robocop ( 1344): {"message":"","time":1419913245007,"expected":"PASS","source":"robocop","status":"FAIL","test":"testAppMenuPathways","thread":null,"subtest":"Waiting for legacy \"More\" menu to open.","action":"test_status","pid":null} Notice that fennec is still initializing: ... 12-29 20:20:39.942 I/dalvikvm( 1344): Could not find method android.view.View.setActivated, referenced from method org.mozilla.gecko.widget.TwoWayView.setupChild 12-29 20:20:39.942 W/dalvikvm( 1344): VFY: unable to resolve virtual method 3841: Landroid/view/View;.setActivated (Z)V 12-29 20:20:39.952 D/dalvikvm( 1344): VFY: replacing opcode 0x6e at 0x00c9 12-29 20:20:39.952 D/dalvikvm( 1344): VFY: dead code 0x00cc-00cc in Lorg/mozilla/gecko/widget/TwoWayView;.setupChild (Landroid/view/View;IIIZZZ)V 12-29 20:20:39.992 I/dalvikvm( 1344): Could not find method android.widget.AdapterView.onInitializeAccessibilityEvent, referenced from method org.mozilla.gecko.widget.TwoWayView.onInitializeAccessibilityEvent 12-29 20:20:40.002 W/dalvikvm( 1344): VFY: unable to resolve virtual method 4174: Landroid/widget/AdapterView;.onInitializeAccessibilityEvent (Landroid/view/accessibility/AccessibilityEvent;)V 12-29 20:20:40.002 D/dalvikvm( 1344): VFY: replacing opcode 0x6f at 0x0000 ... That's not a lot of evidence, but the conclusion I am coming to is that fennec initialization is severely delaying test execution, so that the condition timer is expiring before we have had a chance to retry. If we delayed execution until everything was initialized, we'd likely see a saner range of execution times. I'm not sure what to wait for; we already wait for Gecko:Ready. Also, a longer initialization wait would increase test time for all of the tests. So I think we should probably just increase the maximum wait time for opening the legacy menu...or maybe increase the default wait time for the WaitHelper, in case that avoids similar problems in other tests.
Increase WaitHelper max wait time from 5000 ms to 15000 ms in case initialization is starving the test.
Attachment #8542585 - Flags: review?(michael.l.comella)
(In reply to Geoff Brown [:gbrown] from comment #31) > If we delayed execution until everything was initialized, we'd likely see a > saner range of execution times. I'm not sure what to wait for; we already > wait for Gecko:Ready. Try GeckoHelper.blockForDelayedStartup(). It waits -- appropriately enough -- for delayed startup to have occurred, which fires after main init.
Thanks Richard. Looking at logs for testOSLocale, I see that blockForDelayedStartup typically waits about 30 seconds, which gets us through a ton of initialization activity (although there is often another couple of seconds of those dalvikvm log messages). I like the idea of getting to that quiet, initialized state before testing, but I don't want to pay the price of waiting if I don't absolutely need to: If my increased max wait time is effective, it will allow the test to complete faster, and I think that's important given how long the robocop test suite currently takes.
Yup, makes sense!
Comment on attachment 8542585 [details] [diff] [review] increase WaitHelper default max time from 5000 ms to 15000 ms Review of attachment 8542585 [details] [diff] [review]: ----------------------------------------------------------------- r+ w/ a successful try run. ::: mobile/android/base/tests/helpers/WaitHelper.java @@ +24,5 @@ > */ > public final class WaitHelper { > // TODO: Make public for when Solo.waitForCondition is used directly (i.e. do not want > // assertion from waitFor)? > + private static final int DEFAULT_MAX_WAIT_MS = 15000; Maybe add a comment that the time also works around initialization.
Attachment #8542585 - Flags: review?(michael.l.comella) → review+
(In reply to Michael Comella (:mcomella) from comment #36) > r+ w/ a successful try run. A series of successful try runs - we're checking for intermittents now! :)
https://hg.mozilla.org/mozilla-central/rev/f93e28755637
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 37
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

Creator:
Created:
Updated:
Size: