Intermittent testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false

RESOLVED FIXED in Firefox 33

Status

()

Firefox for Android
General
--
major
RESOLVED FIXED
5 years ago
4 years ago

People

(Reporter: RyanVM, Assigned: gbrown)

Tracking

({intermittent-failure})

15 Branch
Firefox 33
ARM
Android
intermittent-failure
Points:
---

Firefox Tracking Flags

(firefox31 wontfix, firefox32 wontfix, firefox33 fixed, firefox-esr24 unaffected)

Details

Attachments

(1 attachment)

(Reporter)

Description

5 years ago
https://tbpl.mozilla.org/php/getParsedLog.php?id=19296784&tree=Mozilla-Inbound

Android Tegra 250 mozilla-inbound opt test robocop on 2013-01-30 13:25:17 PST for push 6876d078fcdc
slave: tegra-214

0 INFO SimpleTest START
1 INFO TEST-START | testOverscroll
2 INFO TEST-PASS | testOverscroll | Awesomebar URL typed properly - http://mochi.test:8888/tests/robocop/robocop_boxes.html should equal http://mochi.test:8888/tests/robocop/robocop_boxes.html
3 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
4 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(24,101,0,255)  close enough to expected rgb(32,100,0)
5 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,101,33,255)  close enough to expected rgb(0,100,32)
6 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(24,203,33,255)  close enough to expected rgb(32,200,32)
7 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
Exception caught during test!
junit.framework.AssertionFailedError: 7 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
	at junit.framework.Assert.fail(Assert.java:47)
	at org.mozilla.fennec.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:107)
	at org.mozilla.fennec.FennecMochitestAssert.ok(FennecMochitestAssert.java:136)
	at org.mozilla.fennec.FennecMochitestAssert.is(FennecMochitestAssert.java:142)
	at org.mozilla.fennec.tests.PixelTest.waitWithNoPaint(PixelTest.java:63)
	at org.mozilla.fennec.tests.testOverscroll.testOverscroll(testOverscroll.java:35)
	at java.lang.reflect.Method.invokeNative(Native Method)
	at java.lang.reflect.Method.invoke(Method.java:521)
	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
	at org.mozilla.fennec.tests.BaseTest.runTest(BaseTest.java:131)
	at junit.framework.TestCase.runBare(TestCase.java:127)
	at junit.framework.TestResult$1.protect(TestResult.java:106)
	at junit.framework.TestResult.runProtected(TestResult.java:124)
	at junit.framework.TestResult.run(TestResult.java:109)
	at junit.framework.TestCase.run(TestCase.java:118)
	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:520)
	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1447)
8 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Exception caught - junit.framework.AssertionFailedError: 7 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
9 INFO TEST-END | testOverscroll | finished in 35042ms
10 INFO TEST-START | Shutdown
11 INFO Passed: 5
12 INFO Failed: 2
13 INFO Todo: 0
14 INFO SimpleTest FINISHED
(Reporter)

Comment 1

5 years ago
https://tbpl.mozilla.org/php/getParsedLog.php?id=19313427&tree=Mozilla-Inbound
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Guess at rough regression range:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?startdate=2013-01-29&enddate=2013-01-30
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 64

5 years ago
https://tbpl.mozilla.org/php/getParsedLog.php?id=20362035&tree=Mozilla-Inbound
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 89

5 years ago
These logs seem pretty consistent -- several drawFinished events are received at the beginning of the drag:

03-18 23:50:16.088 I/Robocop ( 5467): 5 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,101,33,255)  close enough to expected rgb(0,100,32)
03-18 23:50:16.088 I/Robocop ( 5467): 6 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(24,203,33,255)  close enough to expected rgb(32,200,32)
03-18 23:50:16.088 D/RobocopMotionEventHelper( 5467): Triggering down at (10.0,50.0)
03-18 23:50:19.198 I/GeckoToolbar( 5467): zerdatime 1431076 - Throbber stop
03-18 23:50:19.228 D/RobocopMotionEventHelper( 5467): Triggering move to (10.0,50.0)
03-18 23:50:19.358 D/RobocopMotionEventHelper( 5467): Triggering move to (10.0,55.0)
03-18 23:50:19.378 D/Robocop ( 5467): Received drawFinished notification
03-18 23:50:19.398 D/Robocop ( 5467): Received drawFinished notification
03-18 23:50:19.418 D/Robocop ( 5467): Received drawFinished notification
03-18 23:50:19.438 D/Robocop ( 5467): Received drawFinished notification
03-18 23:50:19.458 D/Robocop ( 5467): Received drawFinished notification
03-18 23:50:19.478 D/Robocop ( 5467): Received drawFinished notification
03-18 23:50:19.508 D/Robocop ( 5467): Received drawFinished notification
03-18 23:50:19.528 D/Robocop ( 5467): Received drawFinished notification
03-18 23:50:23.398 D/RobocopMotionEventHelper( 5467): Triggering move to (10.0,60.0)
03-18 23:50:23.418 D/GeckoFavicons( 5467): Could not get URI for favicon
03-18 23:50:23.458 D/RobocopMotionEventHelper( 5467): Triggering move to (10.0,65.0)
03-18 23:50:23.558 D/RobocopMotionEventHelper( 5467): Triggering move to (10.0,70.0)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 98

5 years ago
(In reply to Ed Morley [:edmorley UTC+0] from comment #26)
> Guess at rough regression range:
> https://hg.mozilla.org/integration/mozilla-inbound/
> pushloghtml?startdate=2013-01-29&enddate=2013-01-30

Also:
 - first appeared on mozilla-aurora 2013-02-09 04:17:07 (Comment 30)
 - first appeared on mozilla-beta 2013-02-20 08:01:22 (Comment 45)
 - never reported on Panda/4.0 -- all reports so far are on Tegra
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 109

5 years ago
AdrianT - Can you have a look at this? We know (comment 89) that the failures occur when drawFinished is received during dragging. That should not happen when we are overscrolling; it we are actually overscrolling and getting paint notifications, then that should probably be investigated by mobile graphics folks. I wonder though if the dragging is not happening the way the test intends it to, or perhaps the zoom level is off sometimes...something like that. It would be nice to catch this happening and "see" it -- ideally get screenshots or a video of a failure.

Another approach might be to investigate the regression range more closely -- see comment 98.
Assignee: nobody → adrian.tamas
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
This is not a graphics issue. It was hard to reproduce but I believe this is caused by bug 791411. There is both a sluggishness after app start ( bug 851861#c59 ) which for me locally was causing a lot of failures and when painting the hole page - probably has something to do with the script execution. There are a lot of DOMContentLoaded and drawFinish notifications. The scroll is correctly executed and visually there is nothing wrong with the test. In my opinion this has to do with the draw notifications for the page load.

I/Robocop ( 3271): 0 INFO SimpleTest START
I/Robocop ( 3271): 1 INFO TEST-START | testOverscroll
I/RobocopMotionEventHelper( 3271): Initialized using offset (0,110)
D/Robocop ( 3271): waiting for Gecko:Ready
D/Robocop ( 3271): Waking up on handleMessage
D/Robocop ( 3271): received event Gecko:Ready
D/Robocop ( 3271): unblocked on expecter for Gecko:Ready
I/Robocop ( 3271): 2 INFO TEST-PASS | testOverscroll | Awesomebar 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
D/Robocop ( 3271): waiting for DOMContentLoaded
D/Robocop ( 3271): Waking up on handleMessage
D/Robocop ( 3271): received event DOMContentLoaded
D/Robocop ( 3271): unblocked on expecter for DOMContentLoaded
I/Robocop ( 3271): 3 INFO TEST-PASS | testOverscroll | Awesomebar URL typed properly - http://mochi.test:8888/tests/robocop/robocop_boxes.html should equal http://mochi.test:8888/tests/robocop/robocop_boxes.html
D/Robocop ( 3271): waiting for DOMContentLoaded
D/Robocop ( 3271): Received drawFinished notification
D/Robocop ( 3271): Received drawFinished notification
D/Robocop ( 3271): Received drawFinished notification
D/Robocop ( 3271): Received drawFinished notification
D/Robocop ( 3271): Received drawFinished notification
D/Robocop ( 3271): Received drawFinished notification
D/Robocop ( 3271): Waking up on handleMessage
D/Robocop ( 3271): received event DOMContentLoaded
D/Robocop ( 3271): Waking up on handleMessage
D/Robocop ( 3271): received event DOMContentLoaded
D/Robocop ( 3271): unblocked on expecter for DOMContentLoaded
D/Robocop ( 3271): Received drawFinished notification
I/Robocop ( 3271): 4 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
I/Robocop ( 3271): 5 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(33,101,0,255)  close enough to expected rgb(32,100,0)
I/Robocop ( 3271): 6 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,101,33,255)  close enough to expected rgb(0,100,32)
I/Robocop ( 3271): 7 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(33,203,33,255)  close enough to expected rgb(32,200,32)
D/RobocopMotionEventHelper( 3271): Triggering down at (10.0,50.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,50.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,55.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,60.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,65.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,70.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,75.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,80.0)
D/Robocop ( 3271): Received drawFinished notification
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,85.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,90.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,95.0)
D/Robocop ( 3271): Received drawFinished notification
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,100.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,105.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,110.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,115.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,120.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,125.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,130.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,135.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,140.0)
D/RobocopMotionEventHelper( 3271): Triggering move to (10.0,150.0)
D/RobocopMotionEventHelper( 3271): Triggering up at (10.0,150.0)
I/Robocop ( 3271): 8 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
I/Robocop ( 3271): Exception caught during test!
I/Robocop ( 3271): junit.framework.AssertionFailedError: 8 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
I/Robocop ( 3271): 	at junit.framework.Assert.fail(Assert.java:47)
I/Robocop ( 3271): 	at org.mozilla.fennec_root.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:107)
I/Robocop ( 3271): 	at org.mozilla.fennec_root.FennecMochitestAssert.ok(FennecMochitestAssert.java:136)
I/Robocop ( 3271): 	at org.mozilla.fennec_root.FennecMochitestAssert.is(FennecMochitestAssert.java:142)
I/Robocop ( 3271): 	at org.mozilla.fennec_root.tests.PixelTest.waitWithNoPaint(PixelTest.java:63)
I/Robocop ( 3271): 	at org.mozilla.fennec_root.tests.testOverscroll.testOverscroll(testOverscroll.java:36)
I/Robocop ( 3271): 	at java.lang.reflect.Method.invokeNative(Native Method)
I/Robocop ( 3271): 	at java.lang.reflect.Method.invoke(Method.java:521)
I/Robocop ( 3271): 	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
I/Robocop ( 3271): 	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
I/Robocop ( 3271): 	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
I/Robocop ( 3271): 	at org.mozilla.fennec_root.tests.BaseTest.runTest(BaseTest.java:125)
I/Robocop ( 3271): 	at junit.framework.TestCase.runBare(TestCase.java:127)
I/Robocop ( 3271): 	at junit.framework.TestResult$1.protect(TestResult.java:106)
I/Robocop ( 3271): 	at junit.framework.TestResult.runProtected(TestResult.java:124)
I/Robocop ( 3271): 	at junit.framework.TestResult.run(TestResult.java:109)
I/Robocop ( 3271): 	at junit.framework.TestCase.run(TestCase.java:118)
I/Robocop ( 3271): 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
I/Robocop ( 3271): 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
I/Robocop ( 3271): 	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:520)
I/Robocop ( 3271): 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1606)
I/Robocop ( 3271): 9 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Exception caught - junit.framework.AssertionFailedError: 8 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
I/Robocop ( 3271): 10 INFO TEST-END | testOverscroll | finished in 118321ms
I/Robocop ( 3271): 11 INFO TEST-START | Shutdown
I/Robocop ( 3271): 12 INFO Passed: 6
I/Robocop ( 3271): 13 INFO Failed: 2
I/Robocop ( 3271): 14 INFO Todo: 0
I/Robocop ( 3271): 15 INFO SimpleTest FINISHED
Increasing the PAINT_CLEAR_DELAY to 5000ms (5s) seems to solve this issue since I am no longer seeing drawFinished notifications displayed while performing the drag which from the above log you can see that is the issue. The panda run seems kind of unstable but I don't think it is caused by the increase in the delay.

Try run:
https://tbpl.mozilla.org/?tree=Try&rev=cf3163073576
(Assignee)

Comment 121

5 years ago
That's interesting! PAINT_CLEAR_DELAY affects both loadAndVerifyBoxes and waitWithNoPaint. I suppose it is the additional load time that is making the difference? Does this mean that the drawFinished notifications received during scrolling are actually left over from the initial load??
Yes the drawFinished is left from the page load. Which makes sense because of my other observation that blockForGeckoReady unblocks to fast leaving the app very sluggish for the first page load.

If the first load is a page with a lot of drawing/a complex page like  robocop_boxes the page will be loaded but it will take some extra time between the unblock by DOMContentLoaded and the last drawFinished notification and also the display of the actual boxes. This on lower end devices like an HTC Desire will cause the loadAndVerifyBoxes to fail with rgb(0,0,0) - the white page background - not close enough to rgb(255,255,255) - the actual color of the first box - error

Another related issue I have seen is that when blockForGeckoReady unblocks the Settings menu is still disabled although they use the same gecko event to trigger unblock/menu item enable. On mobile the Settings menu is disabled until Gecko is fully loaded because there were issues with some options not being accessible until Gecko is loaded.
(Assignee)

Comment 123

5 years ago
(In reply to Adrian Tamas from comment #122)
> of my other observation that blockForGeckoReady unblocks to fast leaving the
> app very sluggish for the first page load.

It looks like blockForGeckoReady is (normally?) waiting for a significant time:

04-15 08:11:31.753 D/Robocop ( 6224): waiting for Gecko:Ready
04-15 08:11:56.903 D/Robocop ( 6224): received event Gecko:Ready

Even waiting for Gecko:Ready makes me a little uneasy, because it doesn't necessarily reflect typical usage. Who waits for 20+ seconds after starting their browser before using it?

I suspect there is still a significant amount of delayed processing happening after Gecko:Ready and that is producing the sluggishness. I wonder what that is? Reader mode? Or is this another symptom of bug 852467 or bug 856621? Or is blockForGeckoReady not always working?
blockForGeckoReady is either always not working or is working correctly but there are other events we have to wait on. On lower end devices I am always seeing the sluggishness after unblock when loading the first page in a test. The normal sluggishness may be further enhanced buy the build being a debug build and not optimized - the build is clearly slower then the standard nightly build from the same sources.

There is bug 766600 which refers to similar issues but that is an older bug. I know there have been talks about improving the cold start experience and there were issues with trying to load pages before Gecko:Ready although I can't find the bug for this. I agree that this is not the real life behavior but we will have to either add a timeout after Gecko:Ready to ensure we can load a page, load a blank/system page before we load a more complex page or if somehow we could unblock only after the "Settings" menu item is enabled which is from what I can observe the last operation Firefox Mobile does before being completely ready for use.
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(OrangeWFM bugs not modified in > 2 months)
Status: NEW → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → WORKSFORME
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Assignee: adrian.tamas → nobody
Comment hidden (Treeherder Robot)
(Assignee)

Comment 146

4 years ago
Occurs intermittently on Android 2.3:

https://tbpl.mozilla.org/php/getParsedLog.php?id=36454224&tree=Ash&full=1
https://tbpl.mozilla.org/php/getParsedLog.php?id=36459785&tree=Ash&full=1
https://tbpl.mozilla.org/php/getParsedLog.php?id=36459804&tree=Ash&full=1

12:31:54     INFO -  0 INFO SimpleTest START
12:31:54     INFO -  1 INFO TEST-START | testOverscroll
12:31:54     INFO -  2 INFO TEST-PASS | testOverscroll | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
12:31:54     INFO -  EventExpecter: no longer listening for Gecko:Ready
12:31:54     INFO -  3 INFO TEST-PASS | testOverscroll | waiting for urlbar text to gain focus - urlbar text gained focus
12:31:54     INFO -  4 INFO TEST-PASS | testOverscroll | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_boxes.html should equal http://mochi.test:8888/tests/robocop/robocop_boxes.html
12:31:54     INFO -  5 INFO TEST-PASS | testOverscroll | Given message occurred for registered event: {"errorType":"","bgColor":"transparent","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded
12:31:54     INFO -  EventExpecter: no longer listening for DOMContentLoaded
12:31:54     INFO -  PaintExpecter: no longer listening for events
12:31:54     INFO -  6 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
12:31:54     INFO -  7 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(32,100,0,255)  close enough to expected rgb(32,100,0)
12:31:54     INFO -  8 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,100,32,255)  close enough to expected rgb(0,100,32)
12:31:54     INFO -  9 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(32,200,32,255)  close enough to expected rgb(32,200,32)
12:31:54     INFO -  10 INFO TEST-PASS | testOverscroll | Checking gecko didn't draw unnecessarily - false should equal false
12:31:54     INFO -  PaintExpecter: no longer listening for events
12:31:54     INFO -  11 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
12:31:54     INFO -  12 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(32,100,0,255)  close enough to expected rgb(32,100,0)
12:31:54     INFO -  13 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,100,32,255)  close enough to expected rgb(0,100,32)
12:31:54     INFO -  14 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(32,200,32,255)  close enough to expected rgb(32,200,32)
12:31:54     INFO -  15 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
12:31:54     INFO -  Exception caught during test!
12:31:54     INFO -  junit.framework.AssertionFailedError: 15 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
12:31:54     INFO -  	at junit.framework.Assert.fail(Assert.java:47)
12:31:54     INFO -  	at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:110)
12:31:54     INFO -  	at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:139)
12:31:54     INFO -  	at org.mozilla.gecko.FennecMochitestAssert.is(FennecMochitestAssert.java:145)
12:31:54     INFO -  	at org.mozilla.gecko.tests.PixelTest.waitWithNoPaint(PixelTest.java:82)
12:31:54     INFO -  	at org.mozilla.gecko.tests.testOverscroll.testOverscroll(testOverscroll.java:44)
12:31:54     INFO -  	at java.lang.reflect.Method.invokeNative(Native Method)
12:31:54     INFO -  	at java.lang.reflect.Method.invoke(Method.java:507)
12:31:54     INFO -  	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
12:31:54     INFO -  	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
12:31:54     INFO -  	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
12:31:54     INFO -  	at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:152)
12:31:54     INFO -  	at junit.framework.TestCase.runBare(TestCase.java:127)
12:31:54     INFO -  	at junit.framework.TestResult$1.protect(TestResult.java:106)
12:31:54     INFO -  	at junit.framework.TestResult.runProtected(TestResult.java:124)
12:31:54     INFO -  	at junit.framework.TestResult.run(TestResult.java:109)
12:31:54     INFO -  	at junit.framework.TestCase.run(TestCase.java:118)
12:31:54     INFO -  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
12:31:54     INFO -  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
12:31:54     INFO -  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:529)
12:31:54     INFO -  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1448)
12:31:54     INFO -  16 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Exception caught - junit.framework.AssertionFailedError: 15 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
12:31:54     INFO -  17 INFO TEST-END | testOverscroll | finished in 114729ms
12:31:54     INFO -  18 INFO TEST-START | Shutdown
12:31:54     INFO -  19 INFO Passed: 13
12:31:54  WARNING -  20 INFO Failed: 2
12:31:54  WARNING -  One or more unittests failed.
12:31:54     INFO -  21 INFO Todo: 0
12:31:54     INFO -  22 INFO SimpleTest FINISHED
12:31:54     INFO -  INFO | automation.py | Application ran for: 0:02:01.501723

12:31:54     INFO -  03-20 12:30:12.912 I/Robocop ( 1852): PaintExpecter: no longer listening for events
12:31:54     INFO -  03-20 12:30:12.922 I/Robocop ( 1852): 11 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
12:31:54     INFO -  03-20 12:30:12.932 I/Robocop ( 1852): 12 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(32,100,0,255)  close enough to expected rgb(32,100,0)
12:31:54     INFO -  03-20 12:30:12.932 I/Robocop ( 1852): 13 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,100,32,255)  close enough to expected rgb(0,100,32)
12:31:54     INFO -  03-20 12:30:12.942 I/Robocop ( 1852): 14 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(32,200,32,255)  close enough to expected rgb(32,200,32)
12:31:54     INFO -  03-20 12:30:12.952 D/RobocopMotionEventHelper( 1852): Triggering down at (50.0,10.0)
12:31:54     INFO -  03-20 12:30:12.982 D/RobocopMotionEventHelper( 1852): Triggering move to (50.0,10.0)
12:31:54     INFO -  03-20 12:30:13.051 D/RobocopMotionEventHelper( 1852): Triggering move to (55.0,10.0)
12:31:54     INFO -  03-20 12:30:13.302 D/RobocopMotionEventHelper( 1852): Triggering move to (60.0,10.0)
12:31:54     INFO -  03-20 12:30:13.633 D/RobocopMotionEventHelper( 1852): Triggering move to (65.0,10.0)
12:31:54     INFO -  03-20 12:30:13.643 E/Profiler( 1852): BPUnw: [8 total] thread_unregister_for_profiling(me=0x297d68) 
12:31:54     INFO -  03-20 12:30:13.712 D/RobocopMotionEventHelper( 1852): Triggering move to (70.0,10.0)
12:31:54     INFO -  03-20 12:30:13.782 D/RobocopMotionEventHelper( 1852): Triggering move to (75.0,10.0)
12:31:54     INFO -  03-20 12:30:13.842 D/RobocopMotionEventHelper( 1852): Triggering move to (80.0,10.0)
12:31:54     INFO -  03-20 12:30:13.912 D/RobocopMotionEventHelper( 1852): Triggering move to (85.0,10.0)
12:31:54     INFO -  03-20 12:30:13.972 D/RobocopMotionEventHelper( 1852): Triggering move to (90.0,10.0)
12:31:54     INFO -  03-20 12:30:14.042 D/RobocopMotionEventHelper( 1852): Triggering move to (95.0,10.0)
12:31:54     INFO -  03-20 12:30:14.134 D/RobocopMotionEventHelper( 1852): Triggering move to (100.0,10.0)
12:31:54     INFO -  03-20 12:30:14.212 D/RobocopMotionEventHelper( 1852): Triggering move to (105.0,10.0)
12:31:54     INFO -  03-20 12:30:14.252 E/GeckoConsole( 1852): [JavaScript Error: "TypeError: Argument 1 of Selection.collapse is not an object." {file: "chrome://browser/content/SelectionHandler.js" line: 295}]
12:31:54     INFO -  03-20 12:30:14.282 D/RobocopMotionEventHelper( 1852): Triggering move to (110.0,10.0)
12:31:54     INFO -  03-20 12:30:14.342 D/RobocopMotionEventHelper( 1852): Triggering move to (115.0,10.0)
12:31:54     INFO -  03-20 12:30:14.422 D/RobocopMotionEventHelper( 1852): Triggering move to (120.0,10.0)
12:31:54     INFO -  03-20 12:30:14.493 D/RobocopMotionEventHelper( 1852): Triggering move to (125.0,10.0)
12:31:54     INFO -  03-20 12:30:14.553 D/RobocopMotionEventHelper( 1852): Triggering move to (130.0,10.0)
12:31:54     INFO -  03-20 12:30:14.623 D/RobocopMotionEventHelper( 1852): Triggering move to (135.0,10.0)
12:31:54     INFO -  03-20 12:30:14.683 D/RobocopMotionEventHelper( 1852): Triggering move to (140.0,10.0)
12:31:54     INFO -  03-20 12:30:14.753 D/Robocop ( 1852): Received drawFinished notification
12:31:54     INFO -  03-20 12:30:14.922 D/Robocop ( 1852): Received drawFinished notification
12:31:54     INFO -  03-20 12:30:15.414 D/Robocop ( 1852): Received drawFinished notification
12:31:54     INFO -  03-20 12:30:15.745 D/RobocopMotionEventHelper( 1852): Triggering move to (150.0,10.0)
12:31:54     INFO -  03-20 12:30:15.792 D/RobocopMotionEventHelper( 1852): Triggering up at (150.0,10.0)
12:31:54     INFO -  03-20 12:30:15.832 D/Robocop ( 1852): Received drawFinished notification
12:31:54     INFO -  03-20 12:30:16.162 D/Robocop ( 1852): Received drawFinished notification
12:31:54     INFO -  03-20 12:30:16.506 D/Robocop ( 1852): Received drawFinished notification
12:31:54     INFO -  03-20 12:30:16.852 D/Robocop ( 1852): Received drawFinished notification
12:31:54     INFO -  03-20 12:30:21.368 E/Profiler( 1852): BPUnw: [7 total] thread_unregister_for_profiling(me=0x2e09e0) 
12:31:54     INFO -  03-20 12:30:25.852 I/Robocop ( 1852): 15 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): Exception caught during test!
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): junit.framework.AssertionFailedError: 15 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at junit.framework.Assert.fail(Assert.java:47)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:110)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:139)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at org.mozilla.gecko.FennecMochitestAssert.is(FennecMochitestAssert.java:145)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at org.mozilla.gecko.tests.PixelTest.waitWithNoPaint(PixelTest.java:82)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at org.mozilla.gecko.tests.testOverscroll.testOverscroll(testOverscroll.java:44)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at java.lang.reflect.Method.invokeNative(Native Method)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at java.lang.reflect.Method.invoke(Method.java:507)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:152)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at junit.framework.TestCase.runBare(TestCase.java:127)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at junit.framework.TestResult$1.protect(TestResult.java:106)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at junit.framework.TestResult.runProtected(TestResult.java:124)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at junit.framework.TestResult.run(TestResult.java:109)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at junit.framework.TestCase.run(TestCase.java:118)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:529)
12:31:54     INFO -  03-20 12:30:26.032 I/Robocop ( 1852): 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1448)
12:31:54     INFO -  03-20 12:30:26.042 I/Robocop ( 1852): 16 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Exception caught - junit.framework.AssertionFailedError: 15 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
12:31:54     INFO -  03-20 12:30:26.052 I/Robocop ( 1852): 17 INFO TEST-END | testOverscroll | finished in 114729ms
12:31:54     INFO -  03-20 12:30:26.052 I/Robocop ( 1852): 18 INFO TEST-START | Shutdown
12:31:54     INFO -  03-20 12:30:26.052 I/Robocop ( 1852): 19 INFO Passed: 13
12:31:54     INFO -  03-20 12:30:26.062 I/Robocop ( 1852): 20 INFO Failed: 2
12:31:54     INFO -  03-20 12:30:26.062 I/Robocop ( 1852): 21 INFO Todo: 0
12:31:54     INFO -  03-20 12:30:26.094 I/Robocop ( 1852): 22 INFO SimpleTest FINISHED
(Assignee)

Comment 147

4 years ago
In contrast, here's logcat from a passing testOverscroll:

03-20 12:28:03.818 I/Robocop ( 1849): 6 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
03-20 12:28:03.828 I/Robocop ( 1849): 7 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(32,100,0,255)  close enough to expected rgb(32,100,0)
03-20 12:28:03.838 I/Robocop ( 1849): 8 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,100,32,255)  close enough to expected rgb(0,100,32)
03-20 12:28:03.838 I/Robocop ( 1849): 9 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(32,200,32,255)  close enough to expected rgb(32,200,32)
03-20 12:28:03.858 D/RobocopMotionEventHelper( 1849): Triggering down at (10.0,50.0)
03-20 12:28:03.898 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,50.0)
03-20 12:28:03.968 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,55.0)
03-20 12:28:04.047 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,60.0)
03-20 12:28:04.118 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,65.0)
03-20 12:28:04.178 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,70.0)
03-20 12:28:04.248 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,75.0)
03-20 12:28:04.318 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,80.0)
03-20 12:28:04.388 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,85.0)
03-20 12:28:04.448 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,90.0)
03-20 12:28:04.518 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,95.0)
03-20 12:28:04.588 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,100.0)
03-20 12:28:04.658 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,105.0)
03-20 12:28:04.738 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,110.0)
03-20 12:28:04.808 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,115.0)
03-20 12:28:04.868 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,120.0)
03-20 12:28:04.997 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,125.0)
03-20 12:28:05.078 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,130.0)
03-20 12:28:05.138 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,135.0)
03-20 12:28:05.208 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,140.0)
03-20 12:28:06.278 D/RobocopMotionEventHelper( 1849): Triggering move to (10.0,150.0)
03-20 12:28:06.298 D/RobocopMotionEventHelper( 1849): Triggering up at (10.0,150.0)
03-20 12:28:07.528 E/GeckoConsole( 1849): 1395343687532	addons.update-checker	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
03-20 12:28:07.558 I/Gecko   ( 1849): 1395343687532	addons.update-checker	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
03-20 12:28:07.618 E/GeckoConsole( 1849): 1395343687622	addons.update-checker	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
03-20 12:28:07.638 I/Gecko   ( 1849): 1395343687622	addons.update-checker	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
03-20 12:28:07.708 E/GeckoConsole( 1849): 1395343687712	addons.update-checker	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
03-20 12:28:07.708 I/Gecko   ( 1849): 1395343687712	addons.update-checker	WARN	Request failed: http://10.0.2.2:8854/extensions-dummy/updateBackgroundURL - 404: Not Found
03-20 12:28:16.390 I/Robocop ( 1849): 10 INFO TEST-PASS | testOverscroll | Checking gecko didn't draw unnecessarily - false should equal false
03-20 12:28:17.118 D/dalvikvm( 1849): GC_FOR_MALLOC freed 3270K, 63% free 3758K/9991K, external 1433K/1945K, paused 73ms
03-20 12:28:17.128 I/dalvikvm-heap( 1849): Grow heap (frag case) to 10.346MB for 3043344-byte allocation
03-20 12:28:17.198 D/dalvikvm( 1849): GC_FOR_MALLOC freed 1K, 33% free 6728K/9991K, external 1433K/1945K, paused 54ms
03-20 12:28:17.868 D/dalvikvm( 1849): GC_CONCURRENT freed <1K, 33% free 6736K/9991K, external 1433K/1945K, paused 7ms+5ms
03-20 12:28:20.558 E/Profiler( 1849): BPUnw: [8 total] thread_unregister_for_profiling(me=0x33c520) 
03-20 12:28:22.508 I/Robocop ( 1849): PaintExpecter: no longer listening for events
03-20 12:28:22.508 I/Robocop ( 1849): 11 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
03-20 12:28:22.508 I/Robocop ( 1849): 12 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(32,100,0,255)  close enough to expected rgb(32,100,0)
03-20 12:28:22.519 I/Robocop ( 1849): 13 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,100,32,255)  close enough to expected rgb(0,100,32)
03-20 12:28:22.528 I/Robocop ( 1849): 14 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(32,200,32,255)  close enough to expected rgb(32,200,32)
03-20 12:28:22.538 D/RobocopMotionEventHelper( 1849): Triggering down at (50.0,10.0)
03-20 12:28:22.568 D/RobocopMotionEventHelper( 1849): Triggering move to (50.0,10.0)
03-20 12:28:22.635 D/RobocopMotionEventHelper( 1849): Triggering move to (55.0,10.0)
03-20 12:28:22.691 D/RobocopMotionEventHelper( 1849): Triggering move to (60.0,10.0)
03-20 12:28:22.763 D/RobocopMotionEventHelper( 1849): Triggering move to (65.0,10.0)
03-20 12:28:22.828 D/RobocopMotionEventHelper( 1849): Triggering move to (70.0,10.0)
03-20 12:28:22.889 D/RobocopMotionEventHelper( 1849): Triggering move to (75.0,10.0)
03-20 12:28:22.950 D/RobocopMotionEventHelper( 1849): Triggering move to (80.0,10.0)
03-20 12:28:23.027 D/RobocopMotionEventHelper( 1849): Triggering move to (85.0,10.0)
03-20 12:28:23.109 D/RobocopMotionEventHelper( 1849): Triggering move to (90.0,10.0)
03-20 12:28:23.172 D/RobocopMotionEventHelper( 1849): Triggering move to (95.0,10.0)
03-20 12:28:23.235 D/RobocopMotionEventHelper( 1849): Triggering move to (100.0,10.0)
03-20 12:28:23.302 D/RobocopMotionEventHelper( 1849): Triggering move to (105.0,10.0)
03-20 12:28:23.374 D/RobocopMotionEventHelper( 1849): Triggering move to (110.0,10.0)
03-20 12:28:23.441 D/RobocopMotionEventHelper( 1849): Triggering move to (115.0,10.0)
03-20 12:28:23.510 D/RobocopMotionEventHelper( 1849): Triggering move to (120.0,10.0)
03-20 12:28:23.578 D/RobocopMotionEventHelper( 1849): Triggering move to (125.0,10.0)
03-20 12:28:23.646 D/RobocopMotionEventHelper( 1849): Triggering move to (130.0,10.0)
03-20 12:28:23.708 D/RobocopMotionEventHelper( 1849): Triggering move to (135.0,10.0)
03-20 12:28:23.768 D/RobocopMotionEventHelper( 1849): Triggering move to (140.0,10.0)
03-20 12:28:24.839 D/RobocopMotionEventHelper( 1849): Triggering move to (150.0,10.0)
03-20 12:28:24.848 D/RobocopMotionEventHelper( 1849): Triggering up at (150.0,10.0)
03-20 12:28:29.739 E/Profiler( 1849): BPUnw: [7 total] thread_unregister_for_profiling(me=0x2b9248) 
03-20 12:28:34.948 I/Robocop ( 1849): 15 INFO TEST-PASS | testOverscroll | Checking gecko didn't draw unnecessarily - false should equal false
03-20 12:28:35.568 D/dalvikvm( 1849): GC_FOR_MALLOC freed 3273K, 63% free 3761K/9991K, external 1433K/1945K, paused 58ms
03-20 12:28:35.568 I/dalvikvm-heap( 1849): Grow heap (frag case) to 10.350MB for 3043344-byte allocation
03-20 12:28:35.678 D/dalvikvm( 1849): GC_CONCURRENT freed 1K, 33% free 6731K/9991K, external 1433K/1945K, paused 8ms+5ms
03-20 12:28:39.868 I/Robocop ( 1849): PaintExpecter: no longer listening for events
03-20 12:28:39.868 I/Robocop ( 1849): 16 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
03-20 12:28:39.877 I/Robocop ( 1849): 17 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(32,100,0,255)  close enough to expected rgb(32,100,0)
03-20 12:28:39.877 I/Robocop ( 1849): 18 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,100,32,255)  close enough to expected rgb(0,100,32)
03-20 12:28:39.888 I/Robocop ( 1849): 19 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(32,200,32,255)  close enough to expected rgb(32,200,32)
03-20 12:28:39.888 I/Robocop ( 1849): 20 INFO TEST-END | testOverscroll | finished in 121214ms
03-20 12:28:39.898 I/Robocop ( 1849): 21 INFO TEST-START | Shutdown
03-20 12:28:39.907 I/Robocop ( 1849): 22 INFO Passed: 18
03-20 12:28:39.907 I/Robocop ( 1849): 23 INFO Failed: 0
03-20 12:28:39.917 I/Robocop ( 1849): 24 INFO Todo: 0
03-20 12:28:39.917 I/Robocop ( 1849): 25 INFO SimpleTest FINISHED

So drawFinished events are usually not generated during this test...but they are sometimes.
(Assignee)

Updated

4 years ago
Blocks: 979921
Whiteboard: [test disabled on Android 2.3]
(Assignee)

Updated

4 years ago
Assignee: nobody → gbrown
(Assignee)

Comment 148

4 years ago
I can no longer reproduce this on Android 2.3, so re-enabling there:

https://hg.mozilla.org/integration/mozilla-inbound/rev/9e673853a28e

Also note that no failures have been reported on other platforms for months -- this seems to be fixed.
Whiteboard: [test disabled on Android 2.3]
https://hg.mozilla.org/mozilla-central/rev/9e673853a28e
Status: REOPENED → RESOLVED
Last Resolved: 4 years ago4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 33
(Reporter)

Updated

4 years ago
Resolution: FIXED → WORKSFORME
(Assignee)

Comment 150

4 years ago
This test has been running trouble-free since being re-enabled on Android 2.3, on ix slaves.

We are now trying to migrate to aws slaves, and when we do, this failure returns.
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 153

4 years ago
Disabled on 2.3: https://hg.mozilla.org/integration/mozilla-inbound/rev/bd582fe109c3
Whiteboard: [leave open] [test disabled on Android 2.3]
https://hg.mozilla.org/mozilla-central/rev/bd582fe109c3
Comment hidden (Treeherder Robot)
(Assignee)

Comment 156

4 years ago
This seems to happen much less frequently now, on Android 2.3 on aws. I was going to re-enable on 2.3 and mark WORKSFORME (again!), when Comment 155 arose:

https://tbpl.mozilla.org/php/getParsedLog.php?id=43200735&tree=Try

22:07:42     INFO -  07-05 21:59:56.896 I/Robocop ( 2324): 11 INFO TEST-PASS | testOverscroll | Pixel at 0, 0 - Color rgba(0,0,0,255)  close enough to expected rgb(0,0,0)
22:07:42     INFO -  07-05 21:59:56.906 I/Robocop ( 2324): 12 INFO TEST-PASS | testOverscroll | Pixel at 100, 0 - Color rgba(32,100,0,255)  close enough to expected rgb(32,100,0)
22:07:42     INFO -  07-05 21:59:56.906 I/Robocop ( 2324): 13 INFO TEST-PASS | testOverscroll | Pixel at 0, 100 - Color rgba(0,100,32,255)  close enough to expected rgb(0,100,32)
22:07:42     INFO -  07-05 21:59:56.916 I/Robocop ( 2324): 14 INFO TEST-PASS | testOverscroll | Pixel at 100, 100 - Color rgba(32,200,32,255)  close enough to expected rgb(32,200,32)
22:07:42     INFO -  07-05 21:59:56.916 D/RobocopMotionEventHelper( 2324): Triggering down at (50.0,10.0)
22:07:42     INFO -  07-05 21:59:56.956 D/RobocopMotionEventHelper( 2324): Triggering move to (50.0,10.0)
22:07:42     INFO -  07-05 21:59:57.265 D/RobocopMotionEventHelper( 2324): Triggering move to (55.0,10.0)
22:07:42     INFO -  07-05 21:59:57.475 D/RobocopMotionEventHelper( 2324): Triggering move to (60.0,10.0)
22:07:42     INFO -  07-05 21:59:57.556 D/RobocopMotionEventHelper( 2324): Triggering move to (65.0,10.0)
22:07:42     INFO -  07-05 21:59:57.627 D/RobocopMotionEventHelper( 2324): Triggering move to (70.0,10.0)
22:07:42     INFO -  07-05 21:59:57.706 D/RobocopMotionEventHelper( 2324): Triggering move to (75.0,10.0)
22:07:42     INFO -  07-05 21:59:57.767 D/RobocopMotionEventHelper( 2324): Triggering move to (80.0,10.0)
22:07:42     INFO -  07-05 21:59:57.836 D/RobocopMotionEventHelper( 2324): Triggering move to (85.0,10.0)
22:07:42     INFO -  07-05 21:59:57.896 D/RobocopMotionEventHelper( 2324): Triggering move to (90.0,10.0)
22:07:42     INFO -  07-05 21:59:57.956 D/RobocopMotionEventHelper( 2324): Triggering move to (95.0,10.0)
22:07:42     INFO -  07-05 21:59:58.026 D/RobocopMotionEventHelper( 2324): Triggering move to (100.0,10.0)
22:07:42     INFO -  07-05 21:59:58.096 D/RobocopMotionEventHelper( 2324): Triggering move to (105.0,10.0)
22:07:42     INFO -  07-05 21:59:58.116 E/GeckoConsole( 2324): [JavaScript Error: "TypeError: Argument 1 of Selection.collapse is not an object." {file: "chrome://browser/content/SelectionHandler.js" line: 336}]
22:07:42     INFO -  07-05 21:59:58.156 D/RobocopMotionEventHelper( 2324): Triggering move to (110.0,10.0)
22:07:42     INFO -  07-05 21:59:58.216 D/RobocopMotionEventHelper( 2324): Triggering move to (115.0,10.0)
22:07:42     INFO -  07-05 21:59:58.285 D/RobocopMotionEventHelper( 2324): Triggering move to (120.0,10.0)
22:07:42     INFO -  07-05 21:59:58.345 D/RobocopMotionEventHelper( 2324): Triggering move to (125.0,10.0)
22:07:42     INFO -  07-05 21:59:58.415 D/RobocopMotionEventHelper( 2324): Triggering move to (130.0,10.0)
22:07:42     INFO -  07-05 21:59:58.476 D/RobocopMotionEventHelper( 2324): Triggering move to (135.0,10.0)
22:07:42     INFO -  07-05 21:59:58.555 D/RobocopMotionEventHelper( 2324): Triggering move to (140.0,10.0)
22:07:42     INFO -  07-05 21:59:58.676 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 21:59:58.846 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 21:59:59.346 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 21:59:59.576 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 21:59:59.628 D/RobocopMotionEventHelper( 2324): Triggering move to (150.0,10.0)
22:07:42     INFO -  07-05 21:59:59.676 D/RobocopMotionEventHelper( 2324): Triggering up at (150.0,10.0)
22:07:42     INFO -  07-05 21:59:59.946 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 22:00:00.348 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 22:00:00.737 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 22:00:01.056 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 22:00:01.497 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 22:00:01.965 D/Robocop ( 2324): Received drawFinished notification
22:07:42     INFO -  07-05 22:00:09.786 I/Robocop ( 2324): 15 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
22:07:42     INFO -  07-05 22:00:09.986 I/Robocop ( 2324): Exception caught during test!
22:07:42     INFO -  07-05 22:00:09.986 I/Robocop ( 2324): junit.framework.AssertionFailedError: 15 INFO TEST-UNEXPECTED-FAIL | testOverscroll | Checking gecko didn't draw unnecessarily - got true, expected false
22:07:42     INFO -  07-05 22:00:09.986 I/Robocop ( 2324): 	at junit.framework.Assert.fail(Assert.java:47)
22:07:42     INFO -  07-05 22:00:09.986 I/Robocop ( 2324): 	at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:111)
22:07:42     INFO -  07-05 22:00:09.986 I/Robocop ( 2324): 	at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:140)
22:07:42     INFO -  07-05 22:00:09.986 I/Robocop ( 2324): 	at org.mozilla.gecko.FennecMochitestAssert.is(FennecMochitestAssert.java:146)
22:07:42     INFO -  07-05 22:00:09.986 I/Robocop ( 2324): 	at org.mozilla.gecko.tests.PixelTest.waitWithNoPaint(PixelTest.java:83)
22:07:42     INFO -  07-05 22:00:09.986 I/Robocop ( 2324): 	at org.mozilla.gecko.tests.testOverscroll.testOverscroll(testOverscroll.java:40)


:kats -- Any ideas? Who might be able to investigate?
Assignee: gbrown → nobody
Flags: needinfo?(bugmail.mozilla)
We don't even have overscroll any more in Fennec. We should just kill this test, because it's not testing anything useful any more.
Flags: needinfo?(bugmail.mozilla)
(Assignee)

Updated

4 years ago
Assignee: nobody → gbrown
(Assignee)

Comment 158

4 years ago
Created attachment 8451731 [details] [diff] [review]
remove testOverscroll
Attachment #8451731 - Flags: review?(bugmail.mozilla)
Attachment #8451731 - Flags: review?(bugmail.mozilla) → review+
(Assignee)

Comment 159

4 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/f9ee3701b0cb
Whiteboard: [leave open] [test disabled on Android 2.3]
https://hg.mozilla.org/mozilla-central/rev/f9ee3701b0cb
Status: REOPENED → RESOLVED
Last Resolved: 4 years ago4 years ago
Resolution: --- → FIXED
(Reporter)

Updated

4 years ago
status-firefox31: --- → wontfix
status-firefox32: --- → wontfix
status-firefox33: --- → fixed
status-firefox-esr24: --- → unaffected
You need to log in before you can comment on or make changes to this bug.