1085609 - Intermittent testDoorHanger | Popup blocker is displayed - got false, expected true

Reporter

Description

•

11 years ago

https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3138576&repo=mozilla-inbound builder Android 2.3 Emulator mozilla-inbound opt test robocop-1 buildid 20141020095914 builduid 8f7592f4f38441999824a8ef8d5507d4 results warnings (1) revision 0970007a8468 slave tst-linux64-spot-1042 starttime Mon Oct 20 2014 13:28:12 GMT-0400 (Eastern Standard Time) 11:30:20 INFO - SimpleTest START 11:30:20 INFO - TEST-START | testDoorHanger 11:30:20 INFO - TEST-PASS | testDoorHanger | Robocop tests need the test device screen to be powered on. - 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready 11:30:20 INFO - EventExpecter: no longer listening for Gecko:Ready 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_geolocation.html should equal http://mochi.test:8888/tests/robocop/robocop_geolocation.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - TEST-PASS | testDoorHanger | Geolocation doorhanger has been displayed - true should equal true 11:30:20 INFO - TEST-PASS | testDoorHanger | Geolocation doorhanger has been hidden when allowing share - false should equal false 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_geolocation.html should equal http://mochi.test:8888/tests/robocop/robocop_geolocation.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"bgColor":"transparent","errorType":"","type":"DOMContentLoaded","metadata":null,"tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - TEST-PASS | testDoorHanger | Geolocation doorhanger has been hidden when denying share - false should equal false 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"type":"Preferences:Data","requestId":29527,"preferences":[{"value":true,"type":"bool","name":"offline-apps.allow_by_default"}]} - Preferences:Data should equal Preferences:Data 11:30:20 INFO - EventExpecter: no longer listening for Preferences:Data 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"type":"Preferences:Data","requestId":0,"preferences":[{"value":false,"type":"bool","name":"offline-apps.allow_by_default"}]} - Preferences:Data should equal Preferences:Data 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting preference array to have one element - 1 should equal 1 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference name to be the same as the set name - offline-apps.allow_by_default should equal offline-apps.allow_by_default 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference type to be the same as the set type - bool should equal bool 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference value to be the same as the set value - false should equal false 11:30:20 INFO - EventExpecter: no longer listening for Preferences:Data 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_offline_storage.html should equal http://mochi.test:8888/tests/robocop/robocop_offline_storage.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"bgColor":"transparent","errorType":"","type":"DOMContentLoaded","metadata":null,"tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - TEST-PASS | testDoorHanger | Offline storage doorhanger notification is hidden when denying storage - false should equal false 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_offline_storage.html should equal http://mochi.test:8888/tests/robocop/robocop_offline_storage.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"bgColor":"transparent","errorType":"","type":"DOMContentLoaded","metadata":null,"tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - TEST-PASS | testDoorHanger | Offline storage doorhanger notification is hidden when allowing storage - false should equal false 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_offline_storage.html should equal http://mochi.test:8888/tests/robocop/robocop_offline_storage.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"bgColor":"transparent","errorType":"","type":"DOMContentLoaded","metadata":null,"tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - TEST-PASS | testDoorHanger | Offline storage doorhanger is no longer triggered - false should equal false 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"type":"Preferences:Data","requestId":-1,"preferences":[{"value":true,"type":"bool","name":"offline-apps.allow_by_default"}]} - Preferences:Data should equal Preferences:Data 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting preference array to have one element - 1 should equal 1 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference name to be the same as the set name - offline-apps.allow_by_default should equal offline-apps.allow_by_default 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference type to be the same as the set type - bool should equal bool 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference value to be the same as the set value - true should equal true 11:30:20 INFO - EventExpecter: no longer listening for Preferences:Data 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_login.html should equal http://mochi.test:8888/tests/robocop/robocop_login.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"bgColor":"transparent","errorType":"","type":"DOMContentLoaded","metadata":null,"tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - TEST-PASS | testDoorHanger | Login doorhanger notification is hidden when denying saving password - false should equal false 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_login.html should equal http://mochi.test:8888/tests/robocop/robocop_login.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"bgColor":"transparent","errorType":"","type":"DOMContentLoaded","metadata":null,"tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - TEST-PASS | testDoorHanger | Login doorhanger notification is hidden when allowing saving password - false should equal false 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"type":"Preferences:Data","requestId":-2,"preferences":[{"value":true,"type":"bool","name":"dom.disable_open_during_load"}]} - Preferences:Data should equal Preferences:Data 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting preference array to have one element - 1 should equal 1 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference name to be the same as the set name - dom.disable_open_during_load should equal dom.disable_open_during_load 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference type to be the same as the set type - bool should equal bool 11:30:20 INFO - TEST-PASS | testDoorHanger | Expecting returned preference value to be the same as the set value - true should equal true 11:30:20 INFO - EventExpecter: no longer listening for Preferences:Data 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_popup.html should equal http://mochi.test:8888/tests/robocop/robocop_popup.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"bgColor":"transparent","errorType":"","type":"DOMContentLoaded","metadata":null,"tabID":0} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - TEST-PASS | testDoorHanger | Popup blocker is displayed - true should equal true 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"parentId":0,"delayLoad":false,"title":"data:text\/plain;charset=utf-8,a","selected":true,"isPrivate":false,"stub":false,"external":false,"desktopMode":false,"tabIndex":-1,"tabID":1,"type":"Tab:Added","uri":"data:text\/plain;charset=utf-8,a"} - Tab:Added should equal Tab:Added 11:30:20 INFO - TEST-PASS | testDoorHanger | Popup blocker is hidden when popup allowed - false should equal false 11:30:20 INFO - TEST-PASS | testDoorHanger | Checking popup URL - data:text/plain;charset=utf-8,a should equal data:text/plain;charset=utf-8,a 11:30:20 INFO - EventExpecter: no longer listening for Tab:Added 11:30:20 INFO - TEST-PASS | testDoorHanger | waiting for urlbar text to gain focus - urlbar text gained focus 11:30:20 INFO - TEST-PASS | testDoorHanger | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_popup.html should equal http://mochi.test:8888/tests/robocop/robocop_popup.html 11:30:20 INFO - TEST-PASS | testDoorHanger | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":2} - DOMContentLoaded should equal DOMContentLoaded 11:30:20 INFO - EventExpecter: no longer listening for DOMContentLoaded 11:30:20 INFO - waitForText timeout on prevented this site from opening 11:30:20 WARNING - TEST-UNEXPECTED-FAIL | testDoorHanger | Popup blocker is displayed - got false, expected true 11:30:20 INFO - 0 ERROR Exception caught during test! - junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testDoorHanger | Popup blocker is displayed - got false, expected true 11:30:20 WARNING - TEST-UNEXPECTED-FAIL | testDoorHanger | Exception caught - junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testDoorHanger | Popup blocker is displayed - got false, expected true 11:30:20 INFO - TEST-OK | testDoorHanger | took 329826ms 11:30:20 INFO - TEST-START | Shutdown 11:30:20 INFO - Passed: 57 11:30:20 INFO - Failed: 2 11:30:20 INFO - Todo: 0 11:30:20 INFO - SimpleTest FINISHED

Comment hidden (Legacy TBPL/Treeherder Robot)

Geoff Brown [:gbrown]

Comment 14

•

11 years ago

02:07:23 INFO - 12-09 01:52:25.557 I/Gecko ( 1852): 02:07:23 INFO - 12-09 01:52:25.557 I/Gecko ( 1852): ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 02:07:23 INFO - 12-09 01:52:25.557 I/Gecko ( 1852): 02:07:23 INFO - 12-09 01:52:31.747 I/Gecko ( 1852): 02:07:23 INFO - 12-09 01:52:31.747 I/Gecko ( 1852): ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost 02:07:23 INFO - 12-09 01:52:31.747 I/Gecko ( 1852): 02:07:23 INFO - 12-09 01:52:35.617 I/Robocop ( 1852): {"action":"log","message":"waitForText timeout on prevented this site from opening","time":1418118755611,"pid":null,"level":"info","source":"robocop","thread":null} 02:07:23 INFO - 12-09 01:52:41.257 I/Robocop ( 1852): {"message":"got false, expected true","time":1418118761255,"expected":"PASS","source":"robocop","status":"FAIL","test":"testDoorHanger","thread":null,"subtest":"Popup blocker is displayed","action":"test_status","pid":null} 02:07:23 INFO - 12-09 01:52:41.467 I/Robocop ( 1852): {"action":"log","message":"Exception caught during test! - junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testDoorHanger | Popup blocker is displayed - got false, expected true\n\tat junit.framework.Assert.fail(Assert.java:47)\n\tat org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:128)\n\tat org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:150)\n\tat org.mozilla.gecko.FennecMochitestAssert.is(FennecMochitestAssert.java:156)\n\tat org.mozilla.gecko.tests.testDoorHanger.testPopupBlocking(testDoorHanger.java:195)\n\tat org.mozilla.gecko.tests.testDoorHanger.testDoorHanger(testDoorHanger.java:148)\n\tat java.lang.reflect.Method.invokeNative(Native Method)\n\tat java.lang.reflect.Method.invoke(Method.java:507)\n\tat android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)\n\tat android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)\n\tat android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)\n\tat org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:163)\n\tat junit.framework.TestCase.runBare(TestCase.java:127)\n\tat junit.framework.TestResult$1.protect(TestResult.java:106)\n\tat junit.framework.TestResult.runProtected(TestResult.java:124)\n\tat junit.framework.TestResult.run(TestResult.java:109)\n\tat junit.framework.TestCase.run(TestCase.java:118)\n\tat android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)\n\tat android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)\n\tat android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:529)\n\tat android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1448)\n","time":1418118761456,"pid":null,"level":"error","source":"robocop","thread":null} 02:07:23 INFO - 12-09 01:52:41.487 I/Robocop ( 1852): {"message":"junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testDoorHanger | Popup blocker is displayed - got false, expected true","time":1418118761478,"expected":"PASS","source":"robocop","status":"FAIL","test":"testDoorHanger","thread":null,"subtest":"Exception caught","action":"test_status","pid":null} 02:07:23 INFO - 12-09 01:52:41.497 I/Robocop ( 1852): {"message":"finished in 296748ms","time":1418118761492,"source":"robocop","status":"OK","test":"testDoorHanger","thread":null,"action":"test_end","pid":null}

Geoff Brown [:gbrown]

Comment 15

•

11 years ago

:margaret added this part of the test in bug 1083879.

:Margaret Leibovic

Updated

•

11 years ago

Assignee: nobody → margaret.leibovic

:Margaret Leibovic

Comment 16

•

11 years ago

It's not immediately clear to me what could be going wrong here. I tried running this locally on a 2.3 device, and it kept dying before it even got to this part of the test :/ Maybe this test is just too large? Should we just disable this on 2.3 devices?

Comment hidden (Legacy TBPL/Treeherder Robot)

:Margaret Leibovic

Comment 112

•

10 years ago

Robin, are you looking for any new bugs to work on? I haven't had time to look into this myself, but you're gaining lots of good intermittent debugging skills, so maybe you would be interested :)

Flags: needinfo?(ricard.robin)

Robin Ricard [:rricard]

Assignee

Comment 113

•

10 years ago

I'm still not done with the other intermittent bug ... (the zoom has been backed out again ... uh !) so I'm not sure I want to take this one right now ... I just want to fix the other (but can't reproduce it locally, making it even more frustrating ...). I'll keep you updated on IRC :)

Flags: needinfo?(ricard.robin)

Robin Ricard [:rricard]

Assignee

Comment 114

•

10 years ago

Waiting for help on the other intermittent bug, I'll start working on this one !

Robin Ricard [:rricard]

Assignee

Comment 115

•

10 years ago

As I see it, the device (an emulator = very slow) just timeouts when waiting for test here. That could mean that the set timeout length is not enough to handle an old 2.3 emulator in our case. All of this is defined in the Robotium's Timeout class (https://github.com/RobotiumTech/robotium/blob/master/robotium-solo/src/main/java/com/robotium/solo/Timeout.java#L55) By default it is set to 20s: https://github.com/RobotiumTech/robotium/blob/b647dc8dc46127d7461e67e0b291789ae735a8e6/robotium-solo/src/main/java/com/robotium/solo/Solo.java#L188 But we can update it at runtime with adb shell commands: https://github.com/RobotiumTech/robotium/blob/89a8601368f6f14bb3cbe61949fe6033b6ab2415/robotium-solo/src/main/java/com/robotium/solo/Timeout.java#L26 Maybe we should make this option greater (30s-40s) on the 2.3 TBPL test device.

Flags: needinfo?(margaret.leibovic)

Robin Ricard [:rricard]

Assignee

Comment 116

•

10 years ago

Source in Mozilla Code: https://dxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/BaseTest.java#382

Robin Ricard [:rricard]

Assignee

Updated

•

10 years ago

Assignee: margaret.leibovic → ricard.robin

Status: NEW → ASSIGNED

Robin Ricard [:rricard]

Assignee

Comment 117

•

10 years ago

Attached patch Intermittent testDoorHanger | Popup blocker is displayed - got false, expected true — Details — Splinter Review

Disable testDoorHanger on 2.3 (temporary, waiting for a refactor)

Attachment #8567138 - Flags: review?(margaret.leibovic)

:Margaret Leibovic

Comment 118

•

10 years ago

Comment on attachment 8567138 [details] [diff] [review] Intermittent testDoorHanger | Popup blocker is displayed - got false, expected true Review of attachment 8567138 [details] [diff] [review]: ----------------------------------------------------------------- Nice, thanks.

Attachment #8567138 - Flags: review?(margaret.leibovic) → review+

:Margaret Leibovic

Updated

•

10 years ago

Depends on: 1135102

:Margaret Leibovic

Updated

•

10 years ago

Flags: needinfo?(margaret.leibovic)

Keywords: checkin-needed

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 119

•

10 years ago

https://hg.mozilla.org/integration/fx-team/rev/a10d797e3d05 Setting [leave open] under the assumption that more work is going to be done in this bug.

Keywords: checkin-needed

Whiteboard: [leave open][fixed-in-fx-team]

:Margaret Leibovic

Comment 120

•

10 years ago

(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #119) > https://hg.mozilla.org/integration/fx-team/rev/a10d797e3d05 > > Setting [leave open] under the assumption that more work is going to be done > in this bug. I think this patch should stop the intermittent failure, and we filed bug 1135102 to investigate breaking up the test as a real solution.

Ryan VanderMeulen [:RyanVM]

Reporter

Updated

•

10 years ago

Whiteboard: [leave open][fixed-in-fx-team] → [fixed-in-fx-team]

Comment hidden (Legacy TBPL/Treeherder Robot)

Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)

Comment 125

•

10 years ago

https://hg.mozilla.org/mozilla-central/rev/a10d797e3d05

Status: ASSIGNED → RESOLVED

Closed: 10 years ago

status-firefox38: --- → fixed

Resolution: --- → FIXED

Whiteboard: [fixed-in-fx-team]

Target Milestone: --- → Firefox 38

Ryan VanderMeulen [:RyanVM]

Reporter

Updated

•

10 years ago

status-firefox36: --- → wontfix

status-firefox37: --- → affected

status-firefox-esr31: --- → unaffected

Ryan VanderMeulen [:RyanVM]

Reporter

Comment 126

•

10 years ago

https://hg.mozilla.org/releases/mozilla-aurora/rev/c2addc7754f1

status-firefox37: affected → fixed

Flags: in-testsuite-

Nobody; OK to take it and work on it

Updated

•

5 years ago

Product: Firefox for Android → Firefox for Android Graveyard