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

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.

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

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

More logging to help debug.

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

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.

comment 85 doesn't have the patch.

The patch in comment 72 is expected to fix this issue so marking as 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.

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.

comment 110 is another timeout.

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

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?

comment 114, comment 115, and comment 117 are bug 952046.

comment 119 is bug 952046.

comment 121 is bug 952046.

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

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?

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.

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.

Android 2.3 is no longer supported in Firefox 48+. Test manifests were updated in bug 1251013.