Closed Bug 995696 Opened 10 years ago Closed 8 years ago

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

Categories

(Firefox for Android Graveyard :: General, defect)

ARM
Android
defect
Not set
normal

Tracking

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

RESOLVED DUPLICATE of bug 1207877
Firefox 34
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)

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: 10 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: 10 years ago10 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: 10 years ago10 years ago
Resolution: --- → FIXED
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 ago9 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: 9 years ago8 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

Created:
Updated:
Size: