Closed Bug 946656 Opened 11 years ago Closed 8 years ago

TEST-UNEXPECTED-FAIL | testSessionHistory | testAboutHomeVisibility | testInputConnection | The Toolbar title is (title) - got (url), expected (title)

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

(firefox27 unaffected, firefox28 fixed, firefox29 fixed, firefox-esr24 unaffected)

Status:
RESOLVED WONTFIX
Milestone:
Firefox 29
Tracking Flags:
Tracking Status
firefox27 --- unaffected
firefox28 --- fixed
firefox29 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: cbook, Assigned: gbrown)

References

(
URL
)

Details

(Keywords: intermittent-failure)

Attachments

(5 files)

Print messages attached to received gecko events.
1.44 KB, patch
Margaret
: review+
Details | Diff | Splinter Review
Add debug output to ToolbarTitleTextChangeVerifier.
3.91 KB, patch
Margaret
: review+
Details | Diff | Splinter Review
Correct regex that determines a loading page in WaitHelper.
3.06 KB, patch
Margaret
: review+
Details | Diff | Splinter Review
Increase state change timeout duration.
1.29 KB, patch
Margaret
: review+
Details | Diff | Splinter Review
Increase toolbar title text change timeout.
1.31 KB, patch
Margaret
: review+
Details | Diff | Splinter Review 
Android 2.2 Tegra fx-team opt test robocop-2 on 2013-12-04 19:47:39 PST for push bf901d895201

slave: tegra-035


https://tbpl.mozilla.org/php/getParsedLog.php?id=31472138&tree=Fx-Team

27 INFO TEST-UNEXPECTED-FAIL | testSessionHistory | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02
12-04 20:26:47.678 I/Robocop ( 8218): 27 INFO TEST-UNEXPECTED-FAIL | testSessionHistory | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02
12-04 20:26:48.788 I/TestRunner( 8218): junit.framework.AssertionFailedError: 27 INFO TEST-UNEXPECTED-FAIL | testSessionHistory | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02
12-04 20:26:47.678 I/Robocop ( 8218): 27 INFO TEST-UNEXPECTED-FAIL | testSessionHistory | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02
12-04 20:26:48.788 I/TestRunner( 8218): junit.framework.AssertionFailedError: 27 INFO TEST-UNEXPECTED-FAIL | testSessionHistory | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02
May be the same issue as bug 938969, although that one seems to be fixed.
(In reply to Michael Comella (:mcomella) from comment #1)
> May be the same issue as bug 938969, although that one seems to be fixed.

https://tbpl.mozilla.org/php/getParsedLog.php?id=31528291&tree=Mozilla-Central seems also be a variant of this
Summary: TEST-UNEXPECTED-FAIL | testSessionHistory | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02 → TEST-UNEXPECTED-FAIL | testSessionHistory | testAboutHomeVisibility | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02
Assignee: nobody → michael.l.comella
try push with a patch to output the data in received GeckoEvents:
  https://tbpl.mozilla.org/?tree=Try&rev=9a8b98b1191a

Should hopefully help diagnose why received events do not time out.
Status: NEW → ASSIGNED
Summary: TEST-UNEXPECTED-FAIL | testSessionHistory | testAboutHomeVisibility | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02 → TEST-UNEXPECTED-FAIL | testSessionHistory | testAboutHomeVisibility | The Toolbar title is Browser Blank Page 02 or 03 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02 also with 03
Comment on attachment 8348254 [details] [diff] [review]
Print messages attached to received gecko events.

This patch will help me with debugging the issue (hopefully) by allowing me to see what the title should be changed to for the DOMTitleChanged event, on the intermittent failures. [1] shows this text is not used anywhere in TBPL logging.

Example output:

12-16 12:03:46.964 I/Robocop ( 3314): 58 INFO TEST-PASS | testAboutHomeVisibility | Given message occurred for registered event: {"type":"DOMTitleChanged","title":"Fennec Home","tabID":0} - DOMTitleChanged should equal DOMTitleChanged

[1]: https://bugzilla.mozilla.org/buglist.cgi?quicksearch=given%20message%20occurred&list_id=8922232
Attachment #8348254 - Flags: review?(margaret.leibovic)
Attachment #8348254 - Flags: review?(margaret.leibovic) → review+
Found via the logs in comment 58:

It seems the failure case is missing the "onTabChanged: TITLE" messages, which eventually calls BrowserToolbar.updateTitle() to set the title. The onTabChanged listeners are called from a background thread (the UI thread) [1], so perhaps we need more time (likely as the logs above comment 30 all come from 2.2 devices, except for comment 38 which is not the same issue).

However, it's strange the ToolbarTitleTextChangeVerifier does not leave a "timed out" comment, however. I wonder if we shouldn't print more data about the ChangeVerifiers (initial state, end state, both timed out and not?) to identify what might be going wrong there.

[1]: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/Tabs.java?rev=0491b6ab227d#577
Attachment #8349145 - Flags: review?(margaret.leibovic) → review+
Flags: needinfo?(margaret.leibovic)
via [1], Android docs on String.matches(String regex):

> This method returns true only if the regular expression matches the entire
> input string. A common mistake is to assume that this method behaves like
> contains(CharSequence);

O_o

Fixed that and made the code more efficient while I was at it by compiling a
Pattern.

[1]: https://developer.android.com/reference/java/lang/String.html#matches%28java.lang.String%29
Attachment #8349773 - Flags: review?(margaret.leibovic)
Note that bug 729495 might break the loading regex if the changes extend to the page title.
I forgot to mention that I expect the patch in comment 72 to solve this bug.
Comment on attachment 8349773 [details] [diff] [review]
Correct regex that determines a loading page in WaitHelper.

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

Tricky. I had to think about this a bit, but it looks good to me.
Attachment #8349773 - Flags: review?(margaret.leibovic) → review+
The patch in comment 72 is expected to fix this issue so marking as fixed.
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Whiteboard: [leave-open]
Target Milestone: --- → Firefox 29
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
It appears that this is a timeout issue (via comment 90):

---
27 INFO TEST-PASS | testSessionHistory | Given message occurred for registered event: {"type":"DOMTitleChanged","title":"Browser Blank Page 02","tabID":0} - DOMTitleChanged should equal DOMTitleChanged
...
ToolbarTitleTextChangeVerifier: timed out.
...
31 INFO TEST-UNEXPECTED-FAIL | testSessionHistory | The Toolbar title is Browser Blank Page 02 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02
---

Comment 91 shows similar issues and both tests failed on armv6 (i.e. slower) devices. If this continues, we can try increasing the timeout, to give more time for the title change event to propagate (we currently wait 5000 millis).
comment 93 and 94 are the same failure, also a timeout, however, on Android 4.0. I guess we should just increase the timeout duration.
Attachment #8356669 - Flags: review?(margaret.leibovic) → review+
https://hg.mozilla.org/mozilla-central/rev/e7d88d482cfe
Status: REOPENED → RESOLVED
Closed: 11 years ago → 10 years ago
Resolution: --- → FIXED
I have absolutely no idea why comment 99 would try to load Twitter - we didn't enter that url. I imagine this could be from another bug? Perhaps a session restore where the url is entered on the current tab but one of the restoring tabs replaces the current tab (I think I've seen that incorrect behavior before).
comment 101 is a legitimate ToolbarTextChangeVerifier timeout. This is (apparently) 1/25 2.2 Opt failures. 4.0 also seems to have run ~20 times without issue.

I suppose we can increase the timeout duration some more, but let's see how frequent of an issue this is.
comment 99 may have gone to Twitter because the option was selected off of the Search Suggestions page. This is not unprecedented (bug 952046 comment 0), but seems uncommon enough.
comment 104 seems to have made a google search with the robocop url. This is probably like comment 99 and the suspected reasoning in comment 103.
comment 106: Another `ToolbarTitleTextChangeVerifier: timed out.` This is the first time in five days (comment 101).
bug 938969 comment 9 is a legitimate timeout; this is the first timeout in five days.
It's pretty ridiculous to think that it will take ten seconds to change the page title, but I think increasing it fifteen might work. :P
Attachment #8369021 - Flags: review?(margaret.leibovic)
Comment on attachment 8369021 [details] [diff] [review]
Increase toolbar title text change timeout.

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

Reluctant r+ ... 15 seconds seems like way too long an interval for entering editing mode, is there something that could be happening besides just the device being really slow?
Attachment #8369021 - Flags: review?(margaret.leibovic) → review+
Summary: TEST-UNEXPECTED-FAIL | testSessionHistory | testAboutHomeVisibility | The Toolbar title is Browser Blank Page 02 or 03 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 02 also with 03 → TEST-UNEXPECTED-FAIL | testSessionHistory | testAboutHomeVisibility | The Toolbar title is Browser Blank Page 01 or 02 or 03 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 01 or 02 or 03
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Summary: TEST-UNEXPECTED-FAIL | testSessionHistory | testAboutHomeVisibility | The Toolbar title is Browser Blank Page 01 or 02 or 03 - got http://mochi.test:8888/tests/robocop/robocop_blank_02.html, expected Browser Blank Page 01 or 02 or 03 → TEST-UNEXPECTED-FAIL | testSessionHistory | testAboutHomeVisibility | testInputConnection | The Toolbar title is (title) - got (url), expected (title)
testAboutHomeVisibility has been running well on Android 2.3 on ix. When we migrate to aws slaves, there is an intermittent failure as seen in Comment 156.

testAboutHomeVisibility disabled on 2.3: https://hg.mozilla.org/integration/mozilla-inbound/rev/c35dc314f2f8
Whiteboard: [leave open] [test disabled on Android 2.3]
Note that the unlanded patch r+'d in comment 113 increases the timeout to 15 seconds, which is what the recently landed change in bug 979600 does for BaseTest on Android 2.3.

(In reply to Geoff Brown [:gbrown] from comment #157)
> testAboutHomeVisibility has been running well on Android 2.3 on ix. When we
> migrate to aws slaves, there is an intermittent failure as seen in Comment
> 156.

Geoff, how frequent is this intermittent failure? Do you think the patch in comment 113 could solve the issue?
Flags: needinfo?(gbrown)
There is limited data, but it looks like this happens about once every 3 runs.

Our recent experience in bug 979600 leaves me feeling pessimistic about increasing the timeout.

On the other hand, these logcats show activity just before and after the failure, so maybe it does just need a little longer:

16:44:16     INFO -  06-20 16:30:33.385 D/GeckoTabs( 1616): handleMessage: Content:LocationChange
16:44:16     INFO -  06-20 16:30:33.417 D/GeckoToolbar( 1616): onTabChanged: TITLE
16:44:16     INFO -  06-20 16:30:33.485 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: TITLE
16:44:16     INFO -  06-20 16:30:33.535 D/GeckoTabs( 1616): handleMessage: Content:SecurityChange
16:44:16     INFO -  06-20 16:30:34.165 D/GeckoToolbar( 1616): onTabChanged: MENU_UPDATED
16:44:16     INFO -  06-20 16:30:34.165 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: MENU_UPDATED
16:44:16     INFO -  06-20 16:30:34.165 D/GeckoToolbar( 1616): onTabChanged: LOCATION_CHANGE
16:44:16     INFO -  06-20 16:30:34.165 D/GeckoToolbarDisplayLayout( 1616): updateFavicon(null)
16:44:16     INFO -  06-20 16:30:34.185 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: LOCATION_CHANGE
16:44:16     INFO -  06-20 16:30:34.215 I/Robocop ( 1616): ToolbarTitleTextChangeVerifier: timed out.
16:44:16     INFO -  06-20 16:30:34.757 I/Robocop ( 1616): 20 INFO TEST-PASS | testAboutHomeVisibility | Waiting for Toolbar to exit editing mode. - 
16:44:16     INFO -  06-20 16:30:34.805 I/Robocop ( 1616): 21 INFO TEST-PASS | testAboutHomeVisibility | The toolbar is not in the editing state - 
16:44:16     INFO -  06-20 16:30:34.815 I/Robocop ( 1616): 22 INFO TEST-UNEXPECTED-FAIL | testAboutHomeVisibility | The Toolbar title is Browser Blank Page 01 - got http://mochi.test:8888/tests/robocop/robocop_blank_01.html, expected Browser Blank Page 01
16:44:16     INFO -  06-20 16:30:34.837 I/Robocop ( 1616): 23 INFO TEST-END | testAboutHomeVisibility | finished in 60259ms
16:44:16     INFO -  06-20 16:30:34.855 I/Robocop ( 1616): 24 INFO TEST-START | Shutdown
16:44:16     INFO -  06-20 16:30:34.865 I/Robocop ( 1616): 25 INFO Passed: 20
16:44:16     INFO -  06-20 16:30:34.885 I/Robocop ( 1616): 26 INFO Failed: 1
16:44:16     INFO -  06-20 16:30:34.905 I/Robocop ( 1616): 27 INFO Todo: 0
16:44:16     INFO -  06-20 16:30:34.925 I/Robocop ( 1616): 28 INFO SimpleTest FINISHED
16:44:16     INFO -  06-20 16:30:34.995 D/Telemetry( 1616): StopUISession: homepanel.1:4becc86b-41eb-429a-a042-88fe8b5a094e, reason=null
16:44:16     INFO -  06-20 16:30:34.995 D/Telemetry( 1616): StopUISession: home.1, reason=null
16:44:16     INFO -  06-20 16:30:35.005 D/GeckoToolbar( 1616): onTabChanged: MENU_UPDATED
16:44:16     INFO -  06-20 16:30:35.015 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: MENU_UPDATED
16:44:16     INFO -  06-20 16:30:35.015 D/GeckoToolbar( 1616): onTabChanged: SECURITY_CHANGE
16:44:16     INFO -  06-20 16:30:35.025 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: SECURITY_CHANGE
16:44:16     INFO -  06-20 16:30:35.135 I/GeckoDump( 1616): Robocop:Quit received -- requesting quit
16:44:16     INFO -  06-20 16:30:35.895 D/GeckoTabs( 1616): handleMessage: DOMTitleChanged
16:44:16     INFO -  06-20 16:30:36.545 D/GeckoToolbar( 1616): onTabChanged: TITLE
16:44:16     INFO -  06-20 16:30:36.675 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: TITLE
16:44:16     INFO -  06-20 16:30:37.335 D/GeckoTabs( 1616): handleMessage: DOMContentLoaded
16:44:16     INFO -  06-20 16:30:37.485 D/GeckoTabs( 1616): handleMessage: Content:PageShow
16:44:16     INFO -  06-20 16:30:37.517 D/GeckoToolbar( 1616): onTabChanged: LOADED
16:44:16     INFO -  06-20 16:30:37.517 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: LOADED
16:44:16     INFO -  06-20 16:30:37.535 D/GeckoToolbar( 1616): onTabChanged: PAGE_SHOW
16:44:16     INFO -  06-20 16:30:37.535 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: PAGE_SHOW
16:44:16     INFO -  06-20 16:30:38.015 D/GeckoTabs( 1616): handleMessage: Tab:ViewportMetadata
16:44:16     INFO -  06-20 16:30:38.025 D/GeckoToolbar( 1616): onTabChanged: VIEWPORT_CHANGE
16:44:16     INFO -  06-20 16:30:38.025 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: VIEWPORT_CHANGE
16:44:16     INFO -  06-20 16:30:38.195 D/GeckoTabs( 1616): handleMessage: Content:StateChange
16:44:16     INFO -  06-20 16:30:38.195 D/GeckoToolbar( 1616): onTabChanged: STOP
16:44:16     INFO -  06-20 16:30:38.242 I/GeckoToolbarDisplayLayout( 1616): zerdatime 1579883 - Throbber stop
16:44:16     INFO -  06-20 16:30:38.335 D/GeckoBrowserApp( 1616): BrowserApp.onTabChanged: 0: STOP


I don't think we have aws slaves on try runs yet, and Ash has a significant backlog, but I'll try that patch when I can and report back here.
(In reply to Michael Comella (:mcomella) from comment #158)
> Geoff, how frequent is this intermittent failure? Do you think the patch in
> comment 113 could solve the issue?

Android 2.3 and Android 2.3 armv6 robocop tests are running on aws slaves now. Here are try runs with and without the patch from comment 113:

https://tbpl.mozilla.org/?tree=Try&rev=4e7034684965 (no patch)
https://tbpl.mozilla.org/?tree=Try&rev=3afb4fd997ca (with patch)

The first thing I notice is that the failure is much less frequent in these try runs: Only one testsAboutHomeVisibility failure in each run (25 retries each), and neither failure is exactly the same as seen earlier on Ash (comment 156).

There are 2 testSessionHistory failures in the unpatched run and none in the patched run, but with such low failure frequency, this may just be coincidence. Looking at those failure logs though, it does again look like those 2 failures may have succeeded if the test had just waited another few seconds.

I'm on the fence about this, but if you want to increase that timeout I wouldn't object; maybe just push one more try run to make sure mine wasn't a lucky anomaly.
Flags: needinfo?(gbrown)
Let's just try it out: https://hg.mozilla.org/integration/fx-team/rev/185b1876c7ff

We can revert if it doesn't appear to make a difference.
Note that testInputConnection and testAboutHomeVisibility are still disabled on 2.3, and testSessionHistory is not.
Not actively working on this.
Assignee: michael.l.comella → nobody
Android 2.3 is no longer supported in Firefox 48+.

Test manifests were updated in bug 1251013.
Assignee: nobody → gbrown
Status: REOPENED → RESOLVED
Closed: 10 years ago → 8 years ago
Resolution: --- → WONTFIX
Whiteboard: [leave open] [test disabled on Android 2.3]
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: