Closed Bug 769919 Opened 8 years ago Closed 7 years ago

Intermittent testBookmark | bookmarks list has 4 children (the default bookmarks) - got 5 (or 0), expected 4

Categories

(Firefox for Android :: General, defect)

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

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 16

People

(Reporter: RyanVM, Assigned: gbrown)

References

Details

(Keywords: intermittent-failure)

Attachments

(5 files, 3 obsolete files)

use BACK key to clear VKB so that bookmark list is not obscured
3.99 KB, patch
jmaher
: review+
Details | Diff | Splinter Review
diagnostic patch
1.62 KB, patch
jmaher
: review+
Details | Diff | Splinter Review
Check adapter count instead of visible list child count in testBookmark
2.41 KB, patch
gbrown
: review+
Details | Diff | Splinter Review
do not send BACK to clear VKB and check for list before continuing
15.42 KB, patch
gbrown
: review+
akeybl
: approval-mozilla-beta+
Details | Diff | Splinter Review
add retry logic to getHistory/Bookmark/AllPagesList
23.33 KB, patch
jmaher
: review+
Details | Diff | Splinter Review 
+++ This bug was initially created as a clone of Bug #730129 +++

https://tbpl.mozilla.org/php/getParsedLog.php?id=13126997&tree=Mozilla-Inbound
Android Tegra 250 mozilla-inbound opt test robocop on 2012-06-30 00:49:58 PDT for push 37776fc33437

0 INFO SimpleTest START
1 INFO TEST-START | testBookmark
2 INFO TEST-PASS | testBookmark | checking that bookmarks list exists - bookmarks list exists
3 INFO TEST-UNEXPECTED-FAIL | testBookmark | bookmarks list has 4 children (the default bookmarks) - got 5, expected 4
Exception caught during test!
junit.framework.AssertionFailedError: 3 INFO TEST-UNEXPECTED-FAIL | testBookmark | bookmarks list has 4 children (the default bookmarks) - got 5, expected 4
	at junit.framework.Assert.fail(Assert.java:47)
	at org.mozilla.fennec.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:107)
	at org.mozilla.fennec.FennecMochitestAssert.ok(FennecMochitestAssert.java:137)
	at org.mozilla.fennec.FennecMochitestAssert.is(FennecMochitestAssert.java:143)
	at org.mozilla.fennec.tests.testBookmark.runAwesomeScreenTest(testBookmark.java:86)
	at org.mozilla.fennec.tests.testBookmark.testBookmark(testBookmark.java:54)
	at java.lang.reflect.Method.invokeNative(Native Method)
	at java.lang.reflect.Method.invoke(Method.java:521)
	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
	at org.mozilla.fennec.tests.BaseTest.runTest(BaseTest.java:93)
	at junit.framework.TestCase.runBare(TestCase.java:127)
	at junit.framework.TestResult$1.protect(TestResult.java:106)
	at junit.framework.TestResult.runProtected(TestResult.java:124)
	at junit.framework.TestResult.run(TestResult.java:109)
	at junit.framework.TestCase.run(TestCase.java:118)
	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:520)
	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1447)
4 INFO TEST-UNEXPECTED-FAIL | testBookmark | Exception caught - junit.framework.AssertionFailedError: 3 INFO TEST-UNEXPECTED-FAIL | testBookmark | bookmarks list has 4 children (the default bookmarks) - got 5, expected 4
5 INFO TEST-END | testBookmark | finished in 16501ms
6 INFO TEST-START | Shutdown
7 INFO Passed: 1
8 INFO Failed: 2
9 INFO Todo: 0
10 INFO SimpleTest FINISHED
Is this intermittent? I'm worried it was caused by bug 759041, but I thought I fixed it (on try) before I pushed.
It's intermittent, maybe only 50% of the time that robocop actually manages to run, though that can be more than 50% of the time that this test runs since robocop will pretend green while skipping tests.
(In reply to Phil Ringnalda (:philor) from comment #10)
> It's intermittent, maybe only 50% of the time that robocop actually manages
> to run, though that can be more than 50% of the time that this test runs
> since robocop will pretend green while skipping tests.

Agreed - it is intermittent. There are many failures, and some passes where testBookmark did not run, or failed silently. There are also some real passes, such as:

https://tbpl.mozilla.org/php/getParsedLog.php?id=13196066&tree=Mozilla-Inbound&full=1
Running locally on a Galaxy S, the test fails consistently - got 4, expected 5 children.

Of note, after the test runs, if I start Fennec and check the bookmarks, the new (5th) bookmark exists.

I tried inserting a long sleep between the bookmark creation and the check -- test continues to fail. Also, the new bookmark is clearly visible on screen before the check...very strange.
Assignee: nobody → gbrown
The failing test is calling ListView.getChildCount() (ViewGroup.getChildCount()); there are some Android q/a articles that caution that this returns the number of *visible* items in the list. Sure enough, on my small-screen phone, only 4 items are visible, the 5th being (just barely!) obscured by the VKB. If I clear the VKB with a Back key before testing, getChildCount() returns 5.
The new testBookmarksTab has a very similar test, and it also fails consistently on my Galaxy S. On tbpl, testBookmarksTab usually (always?) passes when testBookmark passes and usually (always?) fails silently when testBookmark fails.
5 robocop runs at https://tbpl.mozilla.org/?tree=Try&rev=b8006c6ddbd3
 - 4 successful, complete runs of testBookmark
 - 4 successful, complete runs of testBookmarksTab
 - 1 unexplained short run of testBookmarksTab (crash, hang?) which left a bookmark which caused a failure in the subsequent testBookmark
Attachment #639070 - Flags: review?(jmaher)
Comment on attachment 639070 [details] [diff] [review]
use BACK key to clear VKB so that bookmark list is not obscured

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

This looks harmless and probably the right thing to do.  I wonder if we should do this in other tests as well?
Attachment #639070 - Flags: review?(jmaher) → review+
There are getChildCount() calls in testAllPagesTab and testHistoryTab as well, but I don't see those failing (oddly)...I'll keep an eye on those.

https://hg.mozilla.org/integration/mozilla-inbound/rev/05500de40104
https://hg.mozilla.org/mozilla-central/rev/05500de40104
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 16
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
In some of these, at least:

https://tbpl.mozilla.org/php/getParsedLog.php?id=13776399&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=13787859&tree=Profiling
https://tbpl.mozilla.org/php/getParsedLog.php?id=13811155&tree=Firefox

there is an undetected failure in testBookmarksTab, which runs earlier. I think testBookmarksTab is failing to clean up, resulting in the testBookmark failure.


42 INFO TEST-PASS | testBookmarksTab | TextView is filled in - Bookmarks Toolbar
43 INFO TEST-PASS | testBookmarksTab | Correct number of ImageViews visible - 0 should equal 0
44 INFO TEST-PASS | testBookmarksTab | Correct number of TextViews visible - 1 should equal 1
45 INFO TEST-PASS | testBookmarksTab | Back moved up one level - 
46 INFO TEST-PASS | testBookmarksTab | Back moved up one level -
INFO | automation.py | Application ran for: 0:17:29.931003
INFO | automation.py | Reading PID log: /tmp/tmpV6zDIBpidlog
getting files in '/mnt/sdcard/tests/profile/minidumps/'
WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!
Attached patch diagnostic patch — — Splinter Review 
I cannot think of what might be going wrong here, and I have had no luck reproducing this problem locally or on try. I am adding diagnostics in this patch in hopes that seeing the extra bookmark URL will point to a specific problem/solution. 

I intend to [leave open] and remove the extra logging once a solution is in place.
Attachment #650276 - Flags: review?(jmaher)
Comment on attachment 650276 [details] [diff] [review]
diagnostic patch

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

cool!
Attachment #650276 - Flags: review?(jmaher) → review+
Whiteboard: [orange] → [orange][leave open]
Whiteboard: [orange][leave open] → [leave open]
I can reproduce this consistently. getChildCount() returns the number of visible views in the list, but we actually want to check the number of total views in the adapter.
Blocks: 798683
Assignee: gbrown → bnicholson
Attachment #689379 - Flags: review?(gbrown)
Comment on attachment 689379 [details] [diff] [review]
Check adapter count instead of visible list child count in testAllPagesTab

Whoops, wrong bug - this one's about testBookmark.
Attachment #689379 - Attachment is obsolete: true
Attachment #689379 - Flags: review?(gbrown)
I can reproduce this one easily too if I run testBookmark with my phone in landscape orientation.

This should fix the tests by using the adapter count rather than visible item count. This still uses the visible item count when iterating through the list, so we only check items that are visible. Ideally, we'd scroll the lists to verify every view rather than just the ones that are visible, but this should be enough to just fix the failed tests for now.
Attachment #689398 - Flags: review?(gbrown)
Comment on attachment 689398 [details] [diff] [review]
Check adapter count instead of visible list child count in testBookmark

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

I think this is a good change, and will help us to run reliably on a wider range of devices / orientations - thanks!

I am not sure that this will reduce the intermittent failures on tegras. I ran many testBookmark tests on try with and without this patch; unfortunately, I couldn't repro the failure in either case!
https://tbpl.mozilla.org/?tree=Try&rev=7f3e3c166fa2
https://tbpl.mozilla.org/?tree=Try&rev=02e59f1b29a5
Attachment #689398 - Flags: review?(gbrown) → review+
testBookmark was disabled and fails almost consistently when enabled now. The main problem is that the BACK key sent to clear the VKB is no longer necessary - see bug 808408. I have a patch under test.
See Also: → 808408
Assignee: bnicholson → gbrown
The BACK key is no longer necessary; it was causing all the failures. I also made some additional changes to make this test more like the now-reliable testBookmarksTab. Multiple try runs show testBookmark passing consistently. I will mark bug 817339 as a dup of this one as it seems to be addressed as well.
Attachment #696156 - Flags: review?(jmaher)
Comment on attachment 696156 [details] [diff] [review]
do not send BACK to clear VKB and check for list before continuing

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

Thanks!  just a couple nits.

::: mobile/android/base/tests/testBookmark.java.in
@@ -80,5 @@
>          // Open the bookmark list and check the root folder view
>          ListView bookmarksList = openBookmarksList();
>  
> -        // Clear VKB so that list is not obscured
> -        mActions.sendSpecialKey(Actions.SpecialKey.BACK);

we need to check other test cases that do this.  I recall reviewing one recently.

@@ +156,5 @@
>          }
>      }
>  
>      private ListView openBookmarksList() {
> +        final int WAIT_FOR_CHILD_TIMEOUT = 2000;

I thought this was at the baseTest level?
Attachment #696156 - Flags: review?(jmaher) → review+
Updated for review comments. r+ carried.

>::: mobile/android/base/tests/testBookmark.java.in
>@@ -80,5 @@
>>          // Open the bookmark list and check the root folder view
>>          ListView bookmarksList = openBookmarksList();
>>  
>> -        // Clear VKB so that list is not obscured
>> -        mActions.sendSpecialKey(Actions.SpecialKey.BACK);

> we need to check other test cases that do this.  I recall reviewing one 
> recently.

I only found testHistoryTab. BACK is used in various other places, but generally not to clear the VKB.

>> +        final int WAIT_FOR_CHILD_TIMEOUT = 2000;
>
> I thought this was at the baseTest level?

Not really...but I thought that was a good idea, so I combined WAIT_FOR_CHILD_TIMEOUT and MAX_WAIT_MS, and made MAX_WAIT_MS public in BaseTest -- much neater. Thanks.
Attachment #696156 - Attachment is obsolete: true
Attachment #696421 - Flags: review+
Duplicate of this bug: 817339
https://hg.mozilla.org/mozilla-central/rev/9fbba2a7caa1
Status: REOPENED → RESOLVED
Closed: 8 years ago → 8 years ago
Resolution: --- → FIXED
Comment on attachment 696421 [details] [diff] [review]
do not send BACK to clear VKB and check for list before continuing

[Approval Request Comment]
Bug caused by (feature/regressing bug #): this is required to push bug 808408, which is a regression. Sorry I forgot about need it.
User impact if declined: Keyboard doesn't disappear when scrolling through panes in awesomescreen
Testing completed (on m-c, etc.): landed on mc awhile ago
Risk to taking this patch (and alternatives if risky): Low risk, test only
String or UUID changes made by this patch: none
Attachment #696421 - Flags: approval-mozilla-aurora?
Comment on attachment 696421 [details] [diff] [review]
do not send BACK to clear VKB and check for list before continuing

[Triage Comment]
FF19 is now on beta, so approving for that channel.
Attachment #696421 - Flags: approval-mozilla-aurora? → approval-mozilla-beta+
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
From Comment 74:

01-29 22:22:17.117 D/GeckoApp( 3137): State - 983041
01-29 22:22:17.117 D/GeckoApp( 3137): Got a document start event.
01-29 22:22:17.207 I/GeckoApp( 3137): Security Mode - unknown
01-29 22:22:17.267 I/ActivityManager( 1020): Displayed activity org.mozilla.fennec/org.mozilla.gecko.AwesomeBar: 432 ms (total 432 ms)
01-29 22:22:17.297 D/GeckoApp( 3137): State - 786448
01-29 22:22:17.297 D/GeckoApp( 3137): Got a document stop event.
01-29 22:22:17.297 I/ActivityManager( 1020): Start proc org.mozilla.f3nn3c.UpdateService for service org.mozilla.fennec/org.mozilla.gecko.updater.UpdateService: pid=3219 uid=10033 gids={3003, 1015, 1006}
01-29 22:22:17.307 I/CompositorParent( 3137): Unable to renew compositor surface; remaining in paused state
01-29 22:22:17.317 I/GeckoDisplayPortCalculator( 3137): Set strategy VelocityBiasStrategy mult=2.0, threshold=5.1200004, reverse=0.2, dangerBaseX=1.0, dangerBaseY=1.0, dangerIncrX=0.0, dangerIncrY=0.0
01-29 22:22:17.447 D/GeckoAppShell( 3137): Gecko event sync took 292 ms
01-29 22:22:17.457 I/GeckoToolbar( 3137): zerdatime 875068 - Throbber stop
01-29 22:22:17.467 D/GeckoFavicons( 3137): Requesting cancelation of favicon load (3)
01-29 22:22:17.467 D/GeckoFavicons( 3137): Cancelling favicon load (3)
01-29 22:22:17.477 I/GeckoToolbar( 3137): zerdatime 875080 - Throbber stop
01-29 22:22:17.637 I/UpdateService( 3219): next update will be at: Wed Jan 30 22:14:31 GMT+00:00 2013
01-29 22:22:18.127 I/ALL_PAGES( 3137): Got cursor in 1118ms
01-29 22:22:19.629 D/GeckoJarReader( 3137): Jar reader reached end of stack
01-29 22:22:22.967 I/Robocop ( 3137): 2 INFO TEST-PASS | testBookmark | checking that bookmarks list exists - bookmarks list exists
01-29 22:22:22.977 I/Robocop ( 3137): 3 INFO TEST-UNEXPECTED-FAIL | testBookmark | bookmarks list has 4 children (the default bookmarks) - got 0, expected 4
Summary: Intermittent testBookmark | bookmarks list has 4 children (the default bookmarks) - got 5, expected 4 → Intermittent testBookmark | bookmarks list has 4 children (the default bookmarks) - got 5 (or 0), expected 4
These intermittent failures on top sites/bookmarks/history lists have plagued us for too long! I cannot reproduce this particular bug locally, and on try it seems to get harder and harder to reproduce as I add more useful logging. I have found though that most (if not all) errors are transient: If we query the list again a moment later, all is well.

My approach in this patch then is to retry -- up to 3 times -- if the list we get is not what we expect. Sometimes it's not clear what to expect -- how many items should be in the list at that point in time. In those cases I pass -1 as the expected number of items, and that check is skipped. I may be able to reduce the number of these cases by analyzing those tests better -- I'm trying not to get bogged down by details here.

Try run is promising: https://tbpl.mozilla.org/?tree=Try&rev=332c74f4652d&noignore=1 -- and that is with testAllPagesTab enabled as well!
Attachment #719511 - Flags: review?(jmaher)
Comment on attachment 719511 [details] [diff] [review]
add retry logic to getHistory/Bookmark/AllPagesList

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

seems like this is a major change, but mostly due to the number of files.  I think we can clean up more around what this touches as indicated in my detailed comments below.

::: mobile/android/base/tests/BaseTest.java.in
@@ +413,2 @@
>       */
> +    protected ListView getAllPagesList(String waitText, int expectedChildCount) {

can we default this to -1, that is the majority of the values we pass in for this value (on all 3 functions)

@@ +509,2 @@
>          return null;
>      }

can we make a common function to do this:
protected ListView getList(String waitText, int exptectedChildCount, String clickText, String tagText, String listName) {
  <insert getHistoryList with hard coded strings matching variables;>
}

protected ListView getHistoryList(String waitText, int exptectedChildCount) {
   return getList(waitText, expectedChildCount, "History", "history", "getHistoryList")
}

::: mobile/android/base/tests/testBookmarklets.java.in
@@ +47,5 @@
>  
>          Boolean found = false;
>          if (bookmarks == null) {
>              mAsserter.is(true, true, "Did not find the bookmarks section in the awesomebar");
>          } else if (mSolo.waitForText(title)) {

do we still need this waitForText?

::: mobile/android/base/tests/testBookmarksTab.java.in
@@ +52,4 @@
>          mAsserter.isnot(list, null, "checking that bookmarks list exists");
>  
>          int count = list.getAdapter().getCount();
>          mAsserter.is(count, 5, "bookmarks list has 5 children (defaults + a folder)");

do we need this assertion anymore?  We sort of do that by default in the new getBookmarksList()

::: mobile/android/base/tests/testClearPrivateData.java.in
@@ +50,1 @@
>          mAsserter.ok(hList.getAdapter().getCount() == 0,"checking history is cleared ","history is cleared");

do we need the assertion for getCount() == 0 still?

::: mobile/android/base/tests/testHistoryTab.java.in
@@ +103,2 @@
>          final int count = listview.getAdapter().getCount();
>          mAsserter.is(count, 3, "history list has 3 children");

do we need this assertion for count == 3 still?
Attachment #719511 - Flags: review?(jmaher) → review-
Updated to address review comments.
Attachment #719511 - Attachment is obsolete: true
Attachment #719981 - Flags: review?(jmaher)
Comment on attachment 719981 [details] [diff] [review]
add retry logic to getHistory/Bookmark/AllPagesList

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

thanks!
Attachment #719981 - Flags: review?(jmaher) → review+
Duplicate of this bug: 825152
https://hg.mozilla.org/mozilla-central/rev/7f88297be027
Status: REOPENED → RESOLVED
Closed: 8 years ago → 7 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.