Closed Bug 995696 Opened 11 years ago Closed 9 years ago

Intermittent testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus

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

(firefox31 fixed, firefox32 fixed, firefox33 fixed, firefox34 fixed, firefox-esr24 unaffected, firefox-esr31 unaffected)

Status:
RESOLVED DUPLICATE of bug 1207877
Milestone:
Firefox 34
Tracking Flags:
Tracking Status
firefox31 --- fixed
firefox32 --- fixed
firefox33 --- fixed
firefox34 --- fixed
firefox-esr24 --- unaffected
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: gbrown)

References

Details

(Keywords: intermittent-failure)

Attachments

(4 files)

wait for Content:PageShow after adding a new tab
6.35 KB, patch
snorp
: review+
Details | Diff | Splinter Review
wait for Content:PageShow with new tab ID + close tabs at end of test
7.01 KB, patch
snorp
: review+
Details | Diff | Splinter Review
ignore Content:PageShow when tabID is 0
1.35 KB, patch
snorp
: review+
Details | Diff | Splinter Review
screenshot from comment 51
42.36 KB, image/jpeg
Details
https://tbpl.mozilla.org/php/getParsedLog.php?id=37663719&tree=Mozilla-Inbound Android 4.0 Panda mozilla-inbound opt test robocop-3 on 2014-04-11 16:28:24 PDT for push afc7a9404a5f slave: panda-0640 16:47:42 INFO - 0 INFO SimpleTest START 16:47:42 INFO - 1 INFO TEST-START | testNewTab 16:47:42 INFO - 2 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready 16:47:42 INFO - EventExpecter: no longer listening for Gecko:Ready 16:47:42 INFO - 3 INFO TEST-PASS | testNewTab | Checking elements - all elements present 16:47:42 INFO - 4 INFO TEST-PASS | testNewTab | Initial number of tabs correct - 1 should equal 1 16:47:42 INFO - 5 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 16:47:42 INFO - 6 INFO TEST-PASS | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 16:47:42 INFO - 7 INFO TEST-PASS | testNewTab | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_blank_01.html should equal http://mochi.test:8888/tests/robocop/robocop_blank_01.html 16:47:42 INFO - 8 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":1} - DOMContentLoaded should equal DOMContentLoaded 16:47:42 INFO - EventExpecter: no longer listening for DOMContentLoaded 16:47:42 INFO - 9 INFO TEST-PASS | testNewTab | Number of tabs increased - 2 should equal 2 16:47:42 INFO - 10 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 16:47:42 INFO - waitForCondition timeout after 10000 ms. 16:47:42 INFO - 11 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 16:47:42 INFO - Exception caught during test! 16:47:42 INFO - junit.framework.AssertionFailedError: 11 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 16:47:42 INFO - at junit.framework.Assert.fail(Assert.java:47) 16:47:42 INFO - at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:111) 16:47:42 INFO - at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:140) 16:47:42 INFO - at org.mozilla.gecko.tests.BaseTest.focusUrlBar(BaseTest.java:182) 16:47:42 INFO - at org.mozilla.gecko.tests.BaseTest.enterUrl(BaseTest.java:188) 16:47:42 INFO - at org.mozilla.gecko.tests.BaseTest.inputAndLoadUrl(BaseTest.java:219) 16:47:42 INFO - at org.mozilla.gecko.tests.BaseTest.addTab(BaseTest.java:542) 16:47:42 INFO - at org.mozilla.gecko.tests.testNewTab.addTab(testNewTab.java:10) 16:47:42 INFO - at org.mozilla.gecko.tests.testNewTab.testNewTab(testNewTab.java:41) 16:47:42 INFO - at java.lang.reflect.Method.invokeNative(Native Method) 16:47:42 INFO - at java.lang.reflect.Method.invoke(Method.java:511) 16:47:42 INFO - at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:214) 16:47:42 INFO - at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:199) 16:47:42 INFO - at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:192) 16:47:42 INFO - at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:125) 16:47:42 INFO - at junit.framework.TestCase.runBare(TestCase.java:127) 16:47:42 INFO - at junit.framework.TestResult$1.protect(TestResult.java:106) 16:47:42 INFO - at junit.framework.TestResult.runProtected(TestResult.java:124) 16:47:42 INFO - at junit.framework.TestResult.run(TestResult.java:109) 16:47:42 INFO - at junit.framework.TestCase.run(TestCase.java:118) 16:47:42 INFO - at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169) 16:47:42 INFO - at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154) 16:47:42 INFO - at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:545) 16:47:42 INFO - at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1551) 16:47:42 INFO - 12 INFO TEST-UNEXPECTED-FAIL | testNewTab | Exception caught - junit.framework.AssertionFailedError: 11 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 16:47:42 INFO - 13 INFO TEST-END | testNewTab | finished in 26153ms 16:47:42 INFO - 14 INFO TEST-START | Shutdown 16:47:42 INFO - 15 INFO Passed: 9 16:47:42 WARNING - 16 INFO Failed: 2 16:47:42 WARNING - One or more unittests failed. 16:47:42 INFO - 17 INFO Todo: 0 16:47:42 INFO - 18 INFO SimpleTest FINISHED
Reminds me of bug 974552, which is essentially this issue for UITest, though the steps (what we click, what we wait for, etc.) are different.
See Also: → 974552
This happens frequently on Android 2.3, where this test is disabled.
Blocks: 979921
Whiteboard: [test disabled on Android 2.3]
https://tbpl.mozilla.org/php/getParsedLog.php?id=38417150&tree=Mozilla-Inbound
Summary: Intermittent testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus → Intermittent testDoorHanger,testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus
testDoorHanger was recently re-enabled on Android 2.3 and has not yet triggered this failure. testNewTab, if enabled on 2.3, still frequently triggers this failure: https://tbpl.mozilla.org/php/getParsedLog.php?id=41654593&tree=Ash&full=1#error4 20:48:29 INFO - 1 INFO TEST-START | testNewTab 20:48:29 INFO - 2 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready 20:48:29 INFO - EventExpecter: no longer listening for Gecko:Ready 20:48:29 INFO - 3 INFO TEST-PASS | testNewTab | Checking elements - all elements present 20:48:29 INFO - 4 INFO TEST-PASS | testNewTab | Initial number of tabs correct - 1 should equal 1 20:48:29 INFO - 5 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 20:48:29 INFO - waitForCondition timeout after 10000 ms. 20:48:29 INFO - 6 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 20:48:29 INFO - Exception caught during test! 20:48:29 INFO - junit.framework.AssertionFailedError: 6 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 20:48:29 INFO - at junit.framework.Assert.fail(Assert.java:47) 20:48:29 INFO - at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:111) 20:48:29 INFO - at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:140) 20:48:29 INFO - at org.mozilla.gecko.tests.BaseTest.focusUrlBar(BaseTest.java:182) 20:48:29 INFO - at org.mozilla.gecko.tests.BaseTest.enterUrl(BaseTest.java:188) 20:48:29 INFO - at org.mozilla.gecko.tests.BaseTest.inputAndLoadUrl(BaseTest.java:219) 20:48:29 INFO - at org.mozilla.gecko.tests.BaseTest.addTab(BaseTest.java:541) 20:48:29 INFO - at org.mozilla.gecko.tests.testNewTab.addTab(testNewTab.java:10) 20:48:29 INFO - at org.mozilla.gecko.tests.testNewTab.testNewTab(testNewTab.java:36) 20:48:29 INFO - at java.lang.reflect.Method.invokeNative(Native Method) 20:48:29 INFO - at java.lang.reflect.Method.invoke(Method.java:507) 20:48:29 INFO - at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204) 20:48:29 INFO - at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194) 20:48:29 INFO - at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186) 20:48:29 INFO - at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:125) 20:48:29 INFO - at junit.framework.TestCase.runBare(TestCase.java:127) 20:48:29 INFO - at junit.framework.TestResult$1.protect(TestResult.java:106) 20:48:29 INFO - at junit.framework.TestResult.runProtected(TestResult.java:124) 20:48:29 INFO - at junit.framework.TestResult.run(TestResult.java:109) 20:48:29 INFO - at junit.framework.TestCase.run(TestCase.java:118) 20:48:29 INFO - at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169) 20:48:29 INFO - at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154) 20:48:29 INFO - at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:529) 20:48:29 INFO - at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1448) 20:48:29 INFO - 7 INFO TEST-UNEXPECTED-FAIL | testNewTab | Exception caught - junit.framework.AssertionFailedError: 6 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 20:48:29 INFO - 8 INFO TEST-END | testNewTab | finished in 29936ms
Assignee: nobody → gbrown
At issue in this bug is that the test creates a new tab via BaseTest.addTab() by clicking the tab + view and then immediately tries to access the url bar, without waiting for UI changes to complete. SessionTest successfully uses BaseTest.addTab() by wrapping it in an EventExpecter and waiting for Content:PageShow. I simply moved that Content:PageShow wait into BaseTest.addTab() -- now testNewTab works reliably on Android 2.3. The patch also contains some innocuous clean-up/modernization of testNewTab.
Attachment #8441614 - Flags: review?(snorp)
Attachment #8441614 - Flags: review?(snorp) → review+
Whiteboard: [test disabled on Android 2.3]
https://hg.mozilla.org/mozilla-central/rev/2daf3d9be2cb
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 33
This still fails intermittently on Android 2.3 Armv6, on aws. https://tbpl.mozilla.org/php/getParsedLog.php?id=42358807&tree=Ash&full=1#error0 07:43:27 INFO - 0 INFO SimpleTest START 07:43:27 INFO - 1 INFO TEST-START | testNewTab 07:43:27 INFO - 2 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready 07:43:27 INFO - EventExpecter: no longer listening for Gecko:Ready 07:43:27 INFO - 3 INFO TEST-PASS | testNewTab | Checking elements - all elements present 07:43:27 INFO - 4 INFO TEST-PASS | testNewTab | Initial number of tabs correct - 1 should equal 1 07:43:27 INFO - 5 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 07:43:27 INFO - 6 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":1} - Content:PageShow should equal Content:PageShow 07:43:27 INFO - EventExpecter: no longer listening for Content:PageShow 07:43:27 INFO - 7 INFO TEST-PASS | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 07:43:27 INFO - 8 INFO TEST-PASS | testNewTab | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_blank_01.html should equal http://mochi.test:8888/tests/robocop/robocop_blank_01.html 07:43:27 INFO - 9 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded 07:43:27 INFO - EventExpecter: no longer listening for DOMContentLoaded 07:43:27 INFO - 10 INFO TEST-PASS | testNewTab | Number of tabs increased - 2 should equal 2 07:43:27 INFO - 11 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 07:43:27 INFO - 12 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":1} - Content:PageShow should equal Content:PageShow 07:43:27 INFO - EventExpecter: no longer listening for Content:PageShow 07:43:27 INFO - waitForCondition timeout after 10000 ms. 07:43:27 INFO - 13 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 07:43:27 INFO - Exception caught during test! 07:43:27 INFO - junit.framework.AssertionFailedError: 13 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 07:43:27 INFO - at junit.framework.Assert.fail(Assert.java:47) 07:43:27 INFO - at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:111) 07:43:27 INFO - at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:140) 07:43:27 INFO - at org.mozilla.gecko.tests.BaseTest.focusUrlBar(BaseTest.java:199) 07:43:27 INFO - at org.mozilla.gecko.tests.BaseTest.enterUrl(BaseTest.java:205) 07:43:27 INFO - at org.mozilla.gecko.tests.BaseTest.inputAndLoadUrl(BaseTest.java:236) 07:43:27 INFO - at org.mozilla.gecko.tests.BaseTest.addTab(BaseTest.java:567) 07:43:27 INFO - at org.mozilla.gecko.tests.testNewTab.addTab(testNewTab.java:12) 07:43:27 INFO - at org.mozilla.gecko.tests.testNewTab.testNewTab(testNewTab.java:39) 07:43:27 INFO - at java.lang.reflect.Method.invokeNative(Native Method) 07:43:27 INFO - at java.lang.reflect.Method.invoke(Method.java:507) 07:43:27 INFO - at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204) 07:43:27 INFO - at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194) 07:43:27 INFO - at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186) 07:43:27 INFO - at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:142) 07:43:27 INFO - at junit.framework.TestCase.runBare(TestCase.java:127) 07:43:27 INFO - at junit.framework.TestResult$1.protect(TestResult.java:106) 07:43:27 INFO - at junit.framework.TestResult.runProtected(TestResult.java:124) 07:43:27 INFO - at junit.framework.TestResult.run(TestResult.java:109) 07:43:27 INFO - at junit.framework.TestCase.run(TestCase.java:118) 07:43:27 INFO - at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169) 07:43:27 INFO - at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154) 07:43:27 INFO - at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:529) 07:43:27 INFO - at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1448) 07:43:27 INFO - 14 INFO TEST-UNEXPECTED-FAIL | testNewTab | Exception caught - junit.framework.AssertionFailedError: 13 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 07:43:27 INFO - 15 INFO TEST-END | testNewTab | finished in 79125ms 07:43:27 INFO - 16 INFO TEST-START | Shutdown 07:43:27 INFO - 17 INFO Passed: 11 07:43:27 WARNING - 18 INFO Failed: 2 07:43:27 INFO - 06-24 07:37:35.054 I/Robocop ( 2099): 10 INFO TEST-PASS | testNewTab | Number of tabs increased - 2 should equal 2 07:43:27 INFO - 06-24 07:37:35.885 V/GeckoNetworkManager( 2099): Registering receiver. 07:43:27 INFO - 06-24 07:37:36.525 D/GeckoTabs( 2099): handleMessage: SessionHistory:New 07:43:27 INFO - 06-24 07:37:36.965 I/Robocop ( 2099): 11 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 07:43:27 INFO - 06-24 07:37:36.965 D/Robocop ( 2099): waiting for Content:PageShow 07:43:27 INFO - 06-24 07:37:37.004 D/GeckoTabs( 2099): handleMessage: Content:LocationChange 07:43:27 INFO - 06-24 07:37:37.064 D/GeckoTabs( 2099): handleMessage: Content:SecurityChange 07:43:27 INFO - 06-24 07:37:37.145 D/GeckoToolbar( 2099): onTabChanged: THUMBNAIL 07:43:27 INFO - 06-24 07:37:37.145 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 0: THUMBNAIL 07:43:27 INFO - 06-24 07:37:37.156 D/GeckoToolbar( 2099): onTabChanged: THUMBNAIL 07:43:27 INFO - 06-24 07:37:37.169 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: THUMBNAIL 07:43:27 INFO - 06-24 07:37:37.914 D/GeckoTabs( 2099): handleMessage: DOMTitleChanged 07:43:27 INFO - 06-24 07:37:38.018 D/GeckoToolbar( 2099): onTabChanged: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:38.018 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:38.055 D/GeckoToolbar( 2099): onTabChanged: TITLE 07:43:27 INFO - 06-24 07:37:38.137 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: TITLE 07:43:27 INFO - 06-24 07:37:38.188 D/GeckoToolbar( 2099): onTabChanged: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:38.188 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:38.195 D/GeckoToolbar( 2099): onTabChanged: LOCATION_CHANGE 07:43:27 INFO - 06-24 07:37:38.205 D/GeckoToolbarDisplayLayout( 2099): updateFavicon(null) 07:43:27 INFO - 06-24 07:37:38.269 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: LOCATION_CHANGE 07:43:27 INFO - 06-24 07:37:38.277 D/GeckoToolbar( 2099): onTabChanged: SECURITY_CHANGE 07:43:27 INFO - 06-24 07:37:38.277 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: SECURITY_CHANGE 07:43:27 INFO - 06-24 07:37:38.894 D/GeckoTabs( 2099): handleMessage: DOMContentLoaded 07:43:27 INFO - 06-24 07:37:38.924 D/GeckoTabs( 2099): handleMessage: Content:PageShow 07:43:27 INFO - 06-24 07:37:38.934 D/Robocop ( 2099): handleMessage called for: Content:PageShow; expecting: Content:PageShow 07:43:27 INFO - 06-24 07:37:38.964 I/Robocop ( 2099): 12 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":1} - Content:PageShow should equal Content:PageShow 07:43:27 INFO - 06-24 07:37:38.964 D/Robocop ( 2099): received event Content:PageShow 07:43:27 INFO - 06-24 07:37:38.974 D/Robocop ( 2099): unblocked on expecter for Content:PageShow 07:43:27 INFO - 06-24 07:37:38.984 I/Robocop ( 2099): EventExpecter: no longer listening for Content:PageShow 07:43:27 INFO - 06-24 07:37:39.014 D/GeckoToolbar( 2099): onTabChanged: TITLE 07:43:27 INFO - 06-24 07:37:39.054 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: TITLE 07:43:27 INFO - 06-24 07:37:39.085 D/Telemetry( 2099): SendUIEvent: event = action.1 method = actionbar timestamp = 2140072 extras = new_tab 07:43:27 INFO - 06-24 07:37:39.165 D/GeckoTabs( 2099): Setting about: tab favicon inline. 07:43:27 INFO - 06-24 07:37:39.195 D/GeckoToolbar( 2099): onTabChanged: LOADED 07:43:27 INFO - 06-24 07:37:39.217 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: LOADED 07:43:27 INFO - 06-24 07:37:40.034 D/GeckoTabs( 2099): handleMessage: Tab:ViewportMetadata 07:43:27 INFO - 06-24 07:37:40.054 D/GeckoToolbar( 2099): onTabChanged: PAGE_SHOW 07:43:27 INFO - 06-24 07:37:40.054 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: PAGE_SHOW 07:43:27 INFO - 06-24 07:37:40.338 D/GeckoToolbar( 2099): onTabChanged: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:40.338 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:40.349 D/GeckoToolbar( 2099): onTabChanged: ADDED 07:43:27 INFO - 06-24 07:37:40.389 I/GeckoToolbarDisplayLayout( 2099): zerdatime 2141350 - Throbber stop 07:43:27 INFO - 06-24 07:37:40.389 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: ADDED 07:43:27 INFO - 06-24 07:37:40.395 D/GeckoToolbar( 2099): onTabChanged: SELECTED 07:43:27 INFO - 06-24 07:37:40.415 D/GeckoToolbarDisplayLayout( 2099): updateFavicon(android.graphics.Bitmap@40568230) 07:43:27 INFO - 06-24 07:37:40.415 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: SELECTED 07:43:27 INFO - 06-24 07:37:40.465 D/Telemetry( 2099): StartUISession: homepanel.1:4becc86b-41eb-429a-a042-88fe8b5a094e 07:43:27 INFO - 06-24 07:37:40.476 D/Telemetry( 2099): StartUISession: home.1 07:43:27 INFO - 06-24 07:37:40.485 D/GeckoToolbar( 2099): onTabChanged: UNSELECTED 07:43:27 INFO - 06-24 07:37:40.485 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: UNSELECTED 07:43:27 INFO - 06-24 07:37:40.505 D/GeckoTabs( 2099): handleMessage: Content:StateChange 07:43:27 INFO - 06-24 07:37:40.938 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:40.938 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:40.958 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:40.958 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:40.965 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:40.965 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:41.024 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:41.044 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:41.054 D/GeckoThumbnailHelper( 2099): Using new thumbnail size: 242544 (width 326) 07:43:27 INFO - 06-24 07:37:41.054 D/GeckoThumbnailHelper( 2099): Sending thumbnail event: 326, 186 07:43:27 INFO - 06-24 07:37:41.095 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:41.115 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:41.115 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:41.125 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:41.125 W/ResourceType( 2099): Attempt to retrieve bag 0x7f0d009f which is invalid or in a cycle. 07:43:27 INFO - 06-24 07:37:41.208 D/GeckoToolbar( 2099): onTabChanged: VIEWPORT_CHANGE 07:43:27 INFO - 06-24 07:37:41.235 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: VIEWPORT_CHANGE 07:43:27 INFO - 06-24 07:37:41.595 W/TwoWayView( 2099): Constructing LayoutParams with height MATCH_PARENT does not make much sense as the view might change orientation. Falling back to WRAP_CONTENT 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): Error reading favicon 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): java.net.UnknownHostException: mochi.test 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at java.net.InetAddress.lookupHostByName(InetAddress.java:506) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at java.net.InetAddress.getAllByNameImpl(InetAddress.java:294) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at java.net.InetAddress.getAllByName(InetAddress.java:256) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:136) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:164) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:119) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:359) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:487) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:465) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at android.net.http.AndroidHttpClient.execute(AndroidHttpClient.java:243) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.tryDownloadRecurse(LoadFaviconTask.java:128) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.downloadAndDecodeImage(LoadFaviconTask.java:226) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.downloadFavicon(LoadFaviconTask.java:205) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.doInBackground$2d4c763b(LoadFaviconTask.java:374) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.doInBackground$42af7916(LoadFaviconTask.java:42) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.mozilla.gecko.util.UiAsyncTask$BackgroundTaskRunnable.run(UiAsyncTask.java:48) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at android.os.Handler.handleCallback(Handler.java:587) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at android.os.Handler.dispatchMessage(Handler.java:92) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at android.os.Looper.loop(Looper.java:130) 07:43:27 INFO - 06-24 07:37:41.725 E/LoadFaviconTask( 2099): at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:32) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): Error reading favicon 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): java.net.UnknownHostException: mochi.test 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at java.net.InetAddress.lookupHostByName(InetAddress.java:497) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at java.net.InetAddress.getAllByNameImpl(InetAddress.java:294) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at java.net.InetAddress.getAllByName(InetAddress.java:256) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:136) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:164) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:119) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:359) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:487) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:465) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at android.net.http.AndroidHttpClient.execute(AndroidHttpClient.java:243) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.tryDownloadRecurse(LoadFaviconTask.java:128) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.downloadAndDecodeImage(LoadFaviconTask.java:226) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.downloadFavicon(LoadFaviconTask.java:205) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.doInBackground$2d4c763b(LoadFaviconTask.java:414) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.mozilla.gecko.favicons.LoadFaviconTask.doInBackground$42af7916(LoadFaviconTask.java:42) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.mozilla.gecko.util.UiAsyncTask$BackgroundTaskRunnable.run(UiAsyncTask.java:48) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at android.os.Handler.handleCallback(Handler.java:587) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at android.os.Handler.dispatchMessage(Handler.java:92) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at android.os.Looper.loop(Looper.java:130) 07:43:27 INFO - 06-24 07:37:41.845 E/LoadFaviconTask( 2099): at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:32) 07:43:27 INFO - 06-24 07:37:42.135 D/GeckoToolbar( 2099): onTabChanged: STOP 07:43:27 INFO - 06-24 07:37:42.135 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: STOP 07:43:27 INFO - 06-24 07:37:42.215 D/GeckoToolbar( 2099): onTabChanged: FAVICON 07:43:27 INFO - 06-24 07:37:42.215 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 1: FAVICON 07:43:27 INFO - 06-24 07:37:42.335 D/GeckoSuggestedSites( 2099): Number of suggested sites: 4 07:43:27 INFO - 06-24 07:37:42.814 D/GeckoTabs( 2099): handleMessage: Tab:Added 07:43:27 INFO - 06-24 07:37:43.095 D/GeckoTabs( 2099): handleMessage: Content:StateChange 07:43:27 INFO - 06-24 07:37:43.377 D/GeckoToolbar( 2099): onTabChanged: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:43.377 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:43.385 D/GeckoToolbar( 2099): onTabChanged: START 07:43:27 INFO - 06-24 07:37:43.402 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: START 07:43:27 INFO - 06-24 07:37:44.206 D/GeckoTabs( 2099): handleMessage: SessionHistory:New 07:43:27 INFO - 06-24 07:37:44.695 D/GeckoTabs( 2099): handleMessage: Content:LocationChange 07:43:27 INFO - 06-24 07:37:44.745 D/GeckoTabs( 2099): handleMessage: Content:SecurityChange 07:43:27 INFO - 06-24 07:37:45.074 D/GeckoToolbar( 2099): onTabChanged: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:45.074 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: MENU_UPDATED 07:43:27 INFO - 06-24 07:37:45.089 D/GeckoToolbar( 2099): onTabChanged: LOCATION_CHANGE 07:43:27 INFO - 06-24 07:37:45.096 D/GeckoToolbarDisplayLayout( 2099): Ignoring favicon: new image is identical to previous one. 07:43:27 INFO - 06-24 07:37:45.110 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: LOCATION_CHANGE 07:43:27 INFO - 06-24 07:37:45.597 D/GeckoToolbar( 2099): onTabChanged: SECURITY_CHANGE 07:43:27 INFO - 06-24 07:37:45.597 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: SECURITY_CHANGE 07:43:27 INFO - 06-24 07:37:46.157 D/GeckoTabs( 2099): handleMessage: DOMTitleChanged 07:43:27 INFO - 06-24 07:37:46.405 D/GeckoTabs( 2099): handleMessage: DOMContentLoaded 07:43:27 INFO - 06-24 07:37:46.405 D/GeckoToolbar( 2099): onTabChanged: TITLE 07:43:27 INFO - 06-24 07:37:46.435 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: TITLE 07:43:27 INFO - 06-24 07:37:46.529 D/GeckoTabs( 2099): handleMessage: Content:PageShow 07:43:27 INFO - 06-24 07:37:46.625 D/GeckoToolbar( 2099): onTabChanged: LOADED 07:43:27 INFO - 06-24 07:37:46.635 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: LOADED 07:43:27 INFO - 06-24 07:37:46.657 D/GeckoToolbar( 2099): onTabChanged: PAGE_SHOW 07:43:27 INFO - 06-24 07:37:46.657 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: PAGE_SHOW 07:43:27 INFO - 06-24 07:37:46.706 D/GeckoTabs( 2099): handleMessage: Tab:ViewportMetadata 07:43:27 INFO - 06-24 07:37:46.730 D/GeckoToolbar( 2099): onTabChanged: VIEWPORT_CHANGE 07:43:27 INFO - 06-24 07:37:46.730 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: VIEWPORT_CHANGE 07:43:27 INFO - 06-24 07:37:46.934 D/GeckoTabs( 2099): handleMessage: Content:StateChange 07:43:27 INFO - 06-24 07:37:46.944 D/GeckoToolbar( 2099): onTabChanged: STOP 07:43:27 INFO - 06-24 07:37:46.994 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: STOP 07:43:27 INFO - 06-24 07:37:47.457 D/GeckoToolbar( 2099): onTabChanged: THUMBNAIL 07:43:27 INFO - 06-24 07:37:47.457 D/GeckoBrowserApp( 2099): BrowserApp.onTabChanged: 2: THUMBNAIL 07:43:27 INFO - 06-24 07:37:49.265 D/GeckoThumbnailHelper( 2099): handleThumbnailData: 242544 07:43:27 INFO - 06-24 07:37:51.536 I/Robocop ( 2099): waitForCondition timeout after 10000 ms. 07:43:27 INFO - 06-24 07:37:51.565 I/Robocop ( 2099): 13 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): Exception caught during test! 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): junit.framework.AssertionFailedError: 13 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at junit.framework.Assert.fail(Assert.java:47) 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:111) 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:140) 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at org.mozilla.gecko.tests.BaseTest.focusUrlBar(BaseTest.java:199) 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at org.mozilla.gecko.tests.BaseTest.enterUrl(BaseTest.java:205) 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at org.mozilla.gecko.tests.BaseTest.inputAndLoadUrl(BaseTest.java:236) 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at org.mozilla.gecko.tests.BaseTest.addTab(BaseTest.java:567) 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at org.mozilla.gecko.tests.testNewTab.addTab(testNewTab.java:12) 07:43:27 INFO - 06-24 07:37:52.475 I/Robocop ( 2099): at org.mozilla.gecko.tests.testNewTab.testNewTab(testNewTab.java:39)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Disabled on 2.3: https://hg.mozilla.org/integration/mozilla-inbound/rev/15c072c4d3db
Whiteboard: [leave open] [test disabled on Android 2.3]
Summary: Intermittent testDoorHanger,testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus → Intermittent testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus
In the remaining failures, eg https://tbpl.mozilla.org/php/getParsedLog.php?id=43164052&tree=Try&full=1, I noticed that the test was failing after opening a second tab and receiving Content:PageShow -- but for the previous tab: 13:25:30 INFO - 4 INFO TEST-PASS | testNewTab | Initial number of tabs correct - 1 should equal 1 13:25:30 INFO - 5 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 13:25:30 INFO - 6 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":1} - Content:PageShow should equal Content:PageShow 13:25:30 INFO - EventExpecter: no longer listening for Content:PageShow 13:25:30 INFO - 7 INFO TEST-PASS | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 13:25:30 INFO - 8 INFO TEST-PASS | testNewTab | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_blank_01.html should equal http://mochi.test:8888/tests/robocop/robocop_blank_01.html 13:25:30 INFO - 9 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded 13:25:30 INFO - EventExpecter: no longer listening for DOMContentLoaded 13:25:30 INFO - 10 INFO TEST-PASS | testNewTab | Number of tabs increased - 2 should equal 2 13:25:30 INFO - 11 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 13:25:30 INFO - 12 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":1} - Content:PageShow should equal Content:PageShow 13:25:30 INFO - EventExpecter: no longer listening for Content:PageShow 13:25:30 INFO - waitForCondition timeout after 10000 ms. 13:25:30 INFO - 13 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus Notice that we see 2 Content:PageShow's here, both with the same tabID! If I update my previous wait for Content:PageShow to now wait for Content:PageShow with a new tabID, I no longer see this problem. I still ran into another low-frequency intermittent failure: https://tbpl.mozilla.org/php/getParsedLog.php?id=43171646&tree=Try&full=1#error0 -- a SwapBuffers crash on shutdown. It seems like this happens when a there is still page load activity at the end of the test. Closing the newly opened tabs appears to avoid this situation: https://tbpl.mozilla.org/?tree=Try&rev=8ae3377d9b26 (The test previously tried to close tabs at the end of the test, using a UI/robocop approach, but that code is buggy and outdated. I couldn't get it working, so used this approach and deleted the old code.)
Attachment #8451616 - Flags: review?(snorp)
Attachment #8451616 - Flags: review?(snorp) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/006053858a18
Whiteboard: [leave open] [test disabled on Android 2.3]
https://hg.mozilla.org/mozilla-central/rev/006053858a18
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
Resolution: --- → FIXED
(In reply to TBPL Robot from comment #27) Notice "tabID":0 -- I wonder if that is a special case. 15:42:08 INFO - 503 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready 15:42:08 INFO - 504 INFO EventExpecter: no longer listening for Gecko:Ready 15:42:08 INFO - 505 INFO TEST-PASS | testNewTab | Checking elements - all elements present 15:42:08 INFO - 506 INFO TEST-PASS | testNewTab | Initial number of tabs correct - 1 should equal 1 15:42:08 INFO - 507 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 15:42:08 INFO - 508 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":1} - Content:PageShow should equal Content:PageShow 15:42:08 INFO - 509 INFO EventExpecter: no longer listening for Content:PageShow 15:42:08 INFO - 510 INFO TEST-PASS | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 15:42:08 INFO - 511 INFO TEST-PASS | testNewTab | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_blank_01.html should equal http://mochi.test:8888/tests/robocop/robocop_blank_01.html 15:42:08 INFO - 512 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded 15:42:08 INFO - 513 INFO EventExpecter: no longer listening for DOMContentLoaded 15:42:08 INFO - 514 INFO TEST-PASS | testNewTab | Number of tabs increased - 2 should equal 2 15:42:08 INFO - 515 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 15:42:08 INFO - 516 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":0} - Content:PageShow should equal Content:PageShow 15:42:08 INFO - 517 INFO EventExpecter: no longer listening for Content:PageShow 15:42:08 INFO - 518 INFO waitForCondition timeout after 10000 ms. 15:42:08 INFO - 519 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 15:42:08 INFO - 520 INFO Exception caught during test! 15:42:08 INFO - 521 INFO junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 15:42:08 INFO - 522 INFO at junit.framework.Assert.fail(Assert.java:47) 15:42:08 INFO - 523 INFO at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:110) 15:42:08 INFO - 524 INFO at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:139) 15:42:08 INFO - 525 INFO at org.mozilla.gecko.tests.BaseTest.focusUrlBar(BaseTest.java:201) 15:42:08 INFO - 526 INFO at org.mozilla.gecko.tests.BaseTest.enterUrl(BaseTest.java:207) 15:42:08 INFO - 527 INFO at org.mozilla.gecko.tests.BaseTest.inputAndLoadUrl(BaseTest.java:238) 15:42:08 INFO - 528 INFO at org.mozilla.gecko.tests.BaseTest.addTab(BaseTest.java:581) 15:42:08 INFO - 529 INFO at org.mozilla.gecko.tests.testNewTab.addTab(testNewTab.java:12) 15:42:08 INFO - 530 INFO at org.mozilla.gecko.tests.testNewTab.testNewTab(testNewTab.java:39) 15:42:08 INFO - 531 INFO at java.lang.reflect.Method.invokeNative(Native Method) 15:42:08 INFO - 532 INFO at java.lang.reflect.Method.invoke(Method.java:507) 15:42:08 INFO - 533 INFO at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204) 15:42:08 INFO - 534 INFO at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194) 15:42:08 INFO - 535 INFO at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186) 15:42:08 INFO - 536 INFO at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:144) 15:42:08 INFO - 537 INFO at junit.framework.TestCase.runBare(TestCase.java:127) 15:42:08 INFO - 538 INFO at junit.framework.TestResult$1.protect(TestResult.java:106) 15:42:08 INFO - 539 INFO at junit.framework.TestResult.runProtected(TestResult.java:124) 15:42:08 INFO - 540 INFO at junit.framework.TestResult.run(TestResult.java:109) 15:42:08 INFO - 541 INFO at junit.framework.TestCase.run(TestCase.java:118) 15:42:08 INFO - 542 INFO at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169) 15:42:08 INFO - 543 INFO at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154) 15:42:08 INFO - 544 INFO at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:529) 15:42:08 INFO - 545 INFO at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1448)
Blocks: 920512
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(In reply to Geoff Brown [:gbrown] from comment #28) > Notice "tabID":0 -- I wonder if that is a special case. Comments 29, 30, and 31 all have "tabID":0 instead of "tabID":2. 11:26:03 INFO - 369 INFO TEST-START | testNewTab 11:26:03 INFO - 370 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready 11:26:03 INFO - 371 INFO EventExpecter: no longer listening for Gecko:Ready 11:26:03 INFO - 372 INFO TEST-PASS | testNewTab | Checking elements - all elements present 11:26:03 INFO - 373 INFO TEST-PASS | testNewTab | Initial number of tabs correct - 1 should equal 1 11:26:03 INFO - 374 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 11:26:03 INFO - 375 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":1} - Content:PageShow should equal Content:PageShow 11:26:03 INFO - 376 INFO EventExpecter: no longer listening for Content:PageShow 11:26:03 INFO - 377 INFO TEST-PASS | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus 11:26:03 INFO - 378 INFO TEST-PASS | testNewTab | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_blank_01.html should equal http://mochi.test:8888/tests/robocop/robocop_blank_01.html 11:26:03 INFO - 379 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:26:03 INFO - 380 INFO EventExpecter: no longer listening for DOMContentLoaded 11:26:03 INFO - 381 INFO TEST-PASS | testNewTab | Number of tabs increased - 2 should equal 2 11:26:03 INFO - 382 INFO TEST-PASS | testNewTab | waiting for add tab view - add tab view available 11:26:03 INFO - 383 INFO TEST-PASS | testNewTab | Given message occurred for registered event: {"type":"Content:PageShow","tabID":0} - Content:PageShow should equal Content:PageShow 11:26:03 INFO - 384 INFO EventExpecter: no longer listening for Content:PageShow 11:26:03 INFO - 385 INFO waitForCondition timeout after 10000 ms. 11:26:03 INFO - 386 INFO TEST-UNEXPECTED-FAIL | testNewTab | waiting for urlbar text to gain focus - urlbar text gained focus
I think this small refinement to my previous solution will resolve the remaining problem. In a normal/successful test run, I see 2 Content:PageShow events, first with tabID of 1 and then with tabID of 2. In all the recent failures, the second Content:PageShow has tabID 0; this is accepted by the addTab wait loop, which exits, allowing the test to proceed prematurely and ultimately leading to a test failure. In some of those logs, another Content:PageShow can be seen (tabID not logged) which follows the one with tabID 0. I assume that if addTab ignores Content:PageShow with tabID 0, it will subsequently receive the correct one, and everything will work out. https://tbpl.mozilla.org/?tree=Try&rev=32c66f0c7261 demonstrates that this change does no harm, but tabID = 0 occurs too infrequently to reproduce.
Attachment #8473212 - Flags: review?(snorp)
Is tab id 0 about:home? Maybe we should instead suppress that or wait for it to show before starting the test?
Yes, I think tab id 0 is about:home. Waiting for it before starting the test might be problematic since we don't know when the test will start in relation to Fennec: I don't think we can guarantee that we won't miss that event. (I'm thinking of the race we encounter with Gecko:Ready, which we solve with the special purpose blockForGeckoReady code.) How would you suppress it?
(In reply to Geoff Brown [:gbrown] from comment #37) > Yes, I think tab id 0 is about:home. Waiting for it before starting the test > might be problematic since we don't know when the test will start in > relation to Fennec: I don't think we can guarantee that we won't miss that > event. (I'm thinking of the race we encounter with Gecko:Ready, which we > solve with the special purpose blockForGeckoReady code.) Right, we should be able to query if tab 0 has already been shown. If not, wait. Similar to what we do for Gecko:Ready. > > How would you suppress it? Not sure about that one, might not be easily doable.
Attachment #8473212 - Flags: review?(snorp) → review+
Thanks. I'll go with this for now and re-visit the alternatives (Comment 36) if there are any subsequent issues. https://hg.mozilla.org/integration/mozilla-inbound/rev/b4e84ff5a467
https://hg.mozilla.org/mozilla-central/rev/b4e84ff5a467
Status: REOPENED → RESOLVED
Closed: 11 years ago → 10 years ago
Resolution: --- → FIXED
status-firefox33: fixed → affected
status-firefox34: --- → fixed
status-firefox-esr31: --- → unaffected
Target Milestone: Firefox 33 → Firefox 34
I'm still seeing this, including in other tests (e.g., testSearchSuggestions). The TBPL Robot comments also indicate that it's still happening on infra, so reopening. Experimentation locally suggests that it's the first run experience. If I tap 'start browsing', dismissing the dialog, then the test will run to completion. Chenxia, I thought you already looked into this. Any insights?
Status: RESOLVED → REOPENED
Flags: needinfo?(liuche)
Resolution: FIXED → ---
Note that some of the failures here are armv6 / esr31 (Comment 47, 50) -- probably not worth investigating.
Comment 51 and some other recent failures have this curious screenshot: a context menu with items "Paste & Go" / "Paste" / "Copy Address" / "Edit Site Settings" / "Add to Home Screen". This is quite different from what I was seeing when I investigated this bug earlier. Maybe our new tab click is going astray??
Assignee: gbrown → nobody
Is this still a problem now that bug 1120530 is landed? I'm also confused about why the contextmenu is showing up during this test - as far as I can tell, this is the long press menu.
Flags: needinfo?(liuche)
(In reply to Chenxia Liu [:liuche] from comment #56) > Is this still a problem now that bug 1120530 is landed? I would assume it's still an issue. The initial log shows the test trying to re-focus the URL bar a second time, which implies that there's no start pane -- unless we managed to click the URL bar before the pane appeared!
Inactive; closing (see bug 1180138).
Status: REOPENED → RESOLVED
Closed: 10 years ago → 10 years ago
Resolution: --- → WORKSFORME
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
This failure should no longer be possible, due to changes in...
Assignee: nobody → gbrown
Status: REOPENED → RESOLVED
Closed: 10 years ago → 9 years ago
Resolution: --- → DUPLICATE
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: