Closed Bug 927578 Opened 7 years ago Closed 7 years ago

Intermittent testReaderMode | GeckoEventExpecter - blockForEvent timeout: Reader:Added

Categories

(Firefox for Android :: General, defect)

ARM
Android
defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 28
Tracking Status
firefox26 --- unaffected
firefox27 --- fixed
firefox28 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: RyanVM, Assigned: gbrown)

Details

(Keywords: assertion, intermittent-failure)

Attachments

(2 files)

https://tbpl.mozilla.org/php/getParsedLog.php?id=29200283&tree=Mozilla-Inbound

Android 2.2 Tegra mozilla-inbound opt test robocop-2 on 2013-10-16 09:47:38 PDT for push 7652896ed115
slave: tegra-178

0 INFO SimpleTest START
1 INFO TEST-START | testReaderMode
EventExpecter: no longer listening for Gecko:Ready
2 INFO TEST-PASS | testReaderMode | waiting for urlbar text to gain focus - urlbar text gained focus
3 INFO TEST-PASS | testReaderMode | URL typed properly - http://mochi.test:8888/tests/robocop/robocop_text_page.html should equal http://mochi.test:8888/tests/robocop/robocop_text_page.html
EventExpecter: no longer listening for DOMContentLoaded
PaintExpecter: no longer listening for events
EventExpecter: no longer listening for DOMContentLoaded
Dumping ALL the threads!
Thread[GeckoANRReporter,5,main]
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:288)
android.os.MessageQueue.next(MessageQueue.java:146)
android.os.Looper.loop(Looper.java:110)
org.mozilla.gecko.ANRReporter$1.run(ANRReporter.java:104)
java.lang.Thread.run(Thread.java:1096)

Thread[HeapWorker,5,system]
dalvik.system.NativeStart.run(Native Method)

Thread[Compiler,5,system]
dalvik.system.NativeStart.run(Native Method)

Thread[Binder Thread #3,5,main]
dalvik.system.NativeStart.run(Native Method)

Thread[ModernAsyncTask #2,5,main]
java.lang.Object.wait(Native Method)
java.lang.Thread.parkFor(Thread.java:1535)
java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
sun.misc.Unsafe.park(Unsafe.java:317)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1996)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1001)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
java.lang.Thread.run(Thread.java:1096)

Thread[Binder Thread #2,5,main]
dalvik.system.NativeStart.run(Native Method)

Thread[Gecko,5,main]
org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)
org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:340)
org.mozilla.gecko.GeckoThread.run(GeckoThread.java:176)

Thread[GeckoBackgroundThread,5,main]
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:288)
android.os.MessageQueue.next(MessageQueue.java:146)
android.os.Looper.loop(Looper.java:110)
org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:32)

Thread[ModernAsyncTask #3,5,main]
java.lang.Object.wait(Native Method)
java.lang.Thread.parkFor(Thread.java:1535)
java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
sun.misc.Unsafe.park(Unsafe.java:317)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1996)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1001)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
java.lang.Thread.run(Thread.java:1096)

Thread[Timer-0,5,main]
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:326)
java.util.Timer$TimerImpl.run(Timer.java:243)

Thread[ModernAsyncTask #5,5,main]
java.lang.Object.wait(Native Method)
java.lang.Thread.parkFor(Thread.java:1535)
java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
sun.misc.Unsafe.park(Unsafe.java:317)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1996)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1001)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
java.lang.Thread.run(Thread.java:1096)

Thread[Signal Catcher,5,system]
dalvik.system.NativeStart.run(Native Method)

Thread[ModernAsyncTask #4,5,main]
java.lang.Object.wait(Native Method)
java.lang.Thread.parkFor(Thread.java:1535)
java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
sun.misc.Unsafe.park(Unsafe.java:317)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1996)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1001)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
java.lang.Thread.run(Thread.java:1096)

Thread[Binder Thread #1,5,main]
dalvik.system.NativeStart.run(Native Method)

Thread[JDWP,5,system]
dalvik.system.NativeStart.run(Native Method)

Thread[RefQueueWorker@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@486059c0,5,main]
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:326)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:107)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:80)
org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:102)
java.lang.Thread.run(Thread.java:1096)

Thread[pool-1-thread-1,5,main]
java.lang.Object.wait(Native Method)
java.lang.Thread.parkFor(Thread.java:1535)
java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
sun.misc.Unsafe.park(Unsafe.java:317)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1996)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1001)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
java.lang.Thread.run(Thread.java:1096)

Thread[Thread-23,5,main]
dalvik.system.NativeStart.run(Native Method)

Thread[main,5,main]
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:288)
android.os.MessageQueue.next(MessageQueue.java:146)
android.os.Looper.loop(Looper.java:110)
android.app.ActivityThread.main(ActivityThread.java:4627)
java.lang.reflect.Method.invokeNative(Native Method)
java.lang.reflect.Method.invoke(Method.java:521)
com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)
com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
dalvik.system.NativeStart.main(Native Method)

Thread[Instr: org.mozilla.fennec.FennecInstrumentationTestRunner,5,main]
dalvik.system.VMStack.getThreadStackTrace(Native Method)
java.lang.Thread.getStackTrace(Thread.java:788)
java.lang.Thread.getAllStackTraces(Thread.java:669)
org.mozilla.fennec.FennecNativeDriver.logAllStackTraces(FennecNativeDriver.java:411)
org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:151)
org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:137)
org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEventData(FennecNativeActions.java:199)
org.mozilla.fennec.tests.testReaderMode.testReaderMode(testReaderMode.java:47)
java.lang.reflect.Method.invokeNative(Native Method)
java.lang.reflect.Method.invoke(Method.java:521)
android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
org.mozilla.fennec.tests.BaseTest.runTest(BaseTest.java:149)
junit.framework.TestCase.runBare(TestCase.java:127)
junit.framework.TestResult$1.protect(TestResult.java:106)
junit.framework.TestResult.runProtected(TestResult.java:124)
junit.framework.TestResult.run(TestResult.java:109)
junit.framework.TestCase.run(TestCase.java:118)
android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:520)
android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1447)

Thread[ModernAsyncTask #1,5,main]
java.lang.Object.wait(Native Method)
java.lang.Thread.parkFor(Thread.java:1535)
java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
sun.misc.Unsafe.park(Unsafe.java:317)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:131)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1996)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1001)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
java.lang.Thread.run(Thread.java:1096)


4 INFO TEST-UNEXPECTED-FAIL | testReaderMode | GeckoEventExpecter - blockForEvent timeout: Reader:Added
Exception caught during test!
junit.framework.AssertionFailedError: 4 INFO TEST-UNEXPECTED-FAIL | testReaderMode | GeckoEventExpecter - blockForEvent timeout: Reader:Added
	at junit.framework.Assert.fail(Assert.java:47)
	at org.mozilla.fennec.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:111)
	at org.mozilla.fennec.FennecMochitestAssert.ok(FennecMochitestAssert.java:140)
	at org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:152)
	at org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:137)
	at org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEventData(FennecNativeActions.java:199)
	at org.mozilla.fennec.tests.testReaderMode.testReaderMode(testReaderMode.java:47)
	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:149)
	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)
5 INFO TEST-UNEXPECTED-FAIL | testReaderMode | Exception caught - junit.framework.AssertionFailedError: 4 INFO TEST-UNEXPECTED-FAIL | testReaderMode | GeckoEventExpecter - blockForEvent timeout: Reader:Added
6 INFO TEST-END | testReaderMode | finished in 137528ms
7 INFO TEST-START | Shutdown
8 INFO Passed: 2
9 INFO Failed: 2
10 INFO Todo: 0
11 INFO SimpleTest FINISHED
Notice the screenshots in these failures: The tabs view is open. It looks like instead of clicking on the reader icon we are clicking on the tabs icon...or the hit areas are off, or something like that.
From the try runs, note that on success, getReaderIcon() gets a view with:

   hitRect: Rect(0, 0 - 32, 48)
   drawingRect: Rect(0, 0 - 32, 48)
   visibility: 0

But on failure, the view has:

   hitRect: Rect(0, 0 - 0, 0)
   drawingRect: Rect(0, 0 - 0, 0)
   visibility: 8

Now trying a patch that waits for visibility == View.VISIBLE (0): https://tbpl.mozilla.org/?tree=Try&rev=b7b4d4529efc
Yes I noticed that the test tries to access the reader icon view before it is present mainly for slower Tegra devices. I hope this patch fixes the problem, I have integrated two new methods which are checking that the reader icon view is present.

Try server run:
https://tbpl.mozilla.org/?tree=Try&rev=087f8a59057d
Attachment #822266 - Flags: review?(gbrown)
Paul -- My experiments show that this failure occurs when getReaderIcon finds a non-null view, but the view is not visible. That's different from the case you seem to be addressing in your patch. As you can see from my try pushes, I am testing a patch to address the non-null-but-not-visible case. I can extend that to include the null view case as well if you like. 

In your patch, I noticed that the waitForCondition calls are not updating anything in the Condition/isSatisfied. It seems to me that isSatisfied will succeed if readerIcon is non-null before the waitForCondition call and isSatisfied will fail continuously and waitForCondition will timeout if the readerIcon is null before the waitForCondition call.

My latest try push: https://tbpl.mozilla.org/?tree=Try&rev=6ffd7aab78be
The main change here is to wait for the reader icon to be visible. I added a check for a non-null view as well, although I still have not encountered a null reader icon view. The wait must be quite long. I still found 1-in-100ish failures after waiting for visibility for 10 seconds.

Final try run is https://tbpl.mozilla.org/?tree=Try&rev=153041660798. The remaining failures are not related. ("Click can not be completed" is bug 927582; the rc4 failure is a result of my robocop.ini change, not part of this patch.)
Attachment #823382 - Flags: review?(paul.feher)
Comment on attachment 823382 [details] [diff] [review]
wait for visible reader icon before clicking on it

Review of attachment 823382 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me, but I'm not an official mozilla reviewer so if you want you could request an official review
Attachment #823382 - Flags: review?(paul.feher) → review+
Attachment #822266 - Flags: review?(gbrown)
Comment on attachment 823382 [details] [diff] [review]
wait for visible reader icon before clicking on it

:jmaher -- your "official" second opinion please!
Attachment #823382 - Flags: review?(jmaher)
Comment on attachment 823382 [details] [diff] [review]
wait for visible reader icon before clicking on it

Review of attachment 823382 [details] [diff] [review]:
-----------------------------------------------------------------

this looks good,but a deviation from our normal test case flow.  If this is stable, maybe some other test cases could benefit from some similar refactoring?

::: mobile/android/base/tests/testReaderMode.java.in
@@ -42,2 @@
>          loadAndPaint(textUrl);
> -        contentEventExpecter.blockForEvent();

is this a new direction we take to not blockForEvent anymore?

@@ +170,5 @@
> +                        return false;
> +                    return true;
> +                }
> +            };
> +            waitForCondition(visibilityCondition, READER_ICON_MAX_WAIT_MS);

does this block and not return until condition is met or timeout is hit?  is there a way to check the return code here?  It appears that we are checking the icon below.
Attachment #823382 - Flags: review?(jmaher) → review+
(In reply to Joel Maher (:jmaher) from comment #42)
> Comment on attachment 823382 [details] [diff] [review]
> this looks good,but a deviation from our normal test case flow.  If this is
> stable, maybe some other test cases could benefit from some similar
> refactoring?

I have been thinking that too. But there are so many tests now...and so little time!
 
> ::: mobile/android/base/tests/testReaderMode.java.in
> @@ -42,2 @@
> >          loadAndPaint(textUrl);
> > -        contentEventExpecter.blockForEvent();
> 
> is this a new direction we take to not blockForEvent anymore?

loadAndPaint already waits on events. This additional blockForEvent meant that we would be waiting for 2 different types of events at the same time. While not normally a cause for alarm, in this case, the reader list processing is happening in a lower-priority thread, so I thought we should minimize the test cruft that's running at the same time.
 
> @@ +170,5 @@
> > +                        return false;
> > +                    return true;
> > +                }
> > +            };
> > +            waitForCondition(visibilityCondition, READER_ICON_MAX_WAIT_MS);
> 
> does this block and not return until condition is met or timeout is hit?

Yes. Also, it logs on timeout.

> is there a way to check the return code here?  It appears that we are checking
> the icon below.

That is possible. But since a timeout will be logged and the more specific cause of failure will be identified by one of the assertions below, checking the return code becomes pointless.
https://hg.mozilla.org/mozilla-central/rev/47f16b08191a
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 28
You need to log in before you can comment on or make changes to this bug.