Closed Bug 880234 Opened 6 years ago Closed 6 years ago

Intermittent testDeviceSearchEngine | GeckoEventExpecter - blockForEvent timeout: Robocop:Status

Categories

(Firefox for Android :: General, defect)

ARM
Android
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 24

People

(Reporter: RyanVM, Assigned: nalexander)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

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

Android Tegra 250 mozilla-inbound opt test robocop-2 on 2013-06-05 21:22:57 PDT for push a6912e70b705
slave: tegra-152

0 INFO SimpleTest START
1 INFO TEST-START | testDeviceSearchEngine
EventExpecter: no longer listening for Gecko:Ready
Registered listener for Robocop:Status
Loading JavaScript test from http://mochi.test:8888/tests/robocop/robocop_javascript.html?path=testDeviceSearchEngine.js
2 INFO TEST-INFO | testDeviceSearchEngine | (xpcshell/head.js) - test 1 pending
3 INFO TEST-INFO | testDeviceSearchEngine | (xpcshell/head.js) - test 2 pending
4 INFO TEST-INFO | testDeviceSearchEngine | testDeviceSearchEngine.js - Starting test_default
5 INFO TEST-INFO | testDeviceSearchEngine | (xpcshell/head.js) - test 3 pending
6 INFO TEST-INFO | testDeviceSearchEngine | testDeviceSearchEngine.js - Loading search engine
7 INFO TEST-INFO | testDeviceSearchEngine | (xpcshell/head.js) - test 4 pending
8 INFO TEST-INFO | testDeviceSearchEngine | (xpcshell/head.js) - test 4 finished
9 INFO TEST-INFO | testDeviceSearchEngine | (xpcshell/head.js) - test 3 finished
10 INFO TEST-INFO | testDeviceSearchEngine | (xpcshell/head.js) - test 2 finished
11 INFO TEST-INFO | testDeviceSearchEngine | testDeviceSearchEngine.js - Observer: engine-changed for Test search engine
12 INFO TEST-INFO | testDeviceSearchEngine | testDeviceSearchEngine.js - Observer: engine-added for Test search engine
13 INFO TEST-PASS | testDeviceSearchEngine | testDeviceSearchEngine.js - [check_submission : 22] http://example.com/search?q=foo == http://example.com/search?q=foo
14 INFO TEST-PASS | testDeviceSearchEngine | testDeviceSearchEngine.js - [check_submission : 22] http://example.com/search/tablet?q=foo == http://example.com/search/tablet?q=foo
15 INFO TEST-PASS | testDeviceSearchEngine | testDeviceSearchEngine.js - [check_submission : 22] http://example.com/search/phone?q=foo == http://example.com/search/phone?q=foo
16 INFO TEST-INFO | testDeviceSearchEngine | testDeviceSearchEngine.js - Device: phone
17 INFO TEST-PASS | testDeviceSearchEngine | testDeviceSearchEngine.js - [check_submission : 22] http://example.com/search/phone?q=foo == http://example.com/search/phone?q=foo
18 INFO TEST-INFO | testDeviceSearchEngine | (xpcshell/head.js) - test 1 finished
19 INFO TEST-INFO | testDeviceSearchEngine | testDeviceSearchEngine.js - Observer: engine-current for Test search engine
20 INFO TEST-INFO | testDeviceSearchEngine | testDeviceSearchEngine.js - Observer: engine-loaded for Test search engine
Dumping ALL the threads!
Thread[Binder Thread #2,5,main]
dalvik.system.NativeStart.run(Native Method)

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

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

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

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[Signal Catcher,5,system]
dalvik.system.NativeStart.run(Native Method)

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[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:102)
java.lang.Thread.run(Thread.java:1096)

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[Gecko,5,main]
org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)
org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:317)
org.mozilla.gecko.GeckoThread.run(GeckoThread.java:113)

Thread[JDWP,5,system]
dalvik.system.NativeStart.run(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:147)
org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:128)
org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEventData(FennecNativeActions.java:207)
org.mozilla.fennec.tests.JavascriptTest.testJavascript(JavascriptTest.java:117)
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:131)
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[RefQueueWorker@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@48674d08,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[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[Binder Thread #1,5,main]
dalvik.system.NativeStart.run(Native Method)


21 INFO TEST-UNEXPECTED-FAIL | testDeviceSearchEngine | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
EventExpecter: no longer listening for Robocop:Status
Unregistered listener for Robocop:Status
Exception caught during test!
junit.framework.AssertionFailedError: 21 INFO TEST-UNEXPECTED-FAIL | testDeviceSearchEngine | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
	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.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:148)
	at org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:128)
	at org.mozilla.fennec.FennecNativeActions$GeckoEventExpecter.blockForEventData(FennecNativeActions.java:207)
	at org.mozilla.fennec.tests.JavascriptTest.testJavascript(JavascriptTest.java:117)
	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)
22 INFO TEST-UNEXPECTED-FAIL | testDeviceSearchEngine | Exception caught - junit.framework.AssertionFailedError: 21 INFO TEST-UNEXPECTED-FAIL | testDeviceSearchEngine | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
23 INFO TEST-END | testDeviceSearchEngine | finished in 109953ms
24 INFO TEST-START | Shutdown
25 INFO Passed: 19
26 INFO Failed: 2
27 INFO Todo: 0
28 INFO SimpleTest FINISHED
This problem is happening in JavaScriptTest. Have we seen this failure with any other tests?
(In reply to :Margaret Leibovic from comment #1)
> This problem is happening in JavaScriptTest. Have we seen this failure with
> any other tests?

JavascriptTest waits for Robocop:Status messages from the test harness, which correspond to head.js output lines (xpcshell's head.js, slightly modified).  That's how it knows when tests pass, or fail, or the suite ends.

I'm not certain that do_test_pending() works with add_task() -- see http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/testDeviceSearchEngine.js#51.  Does that work with xpcshell?

Otherwise, this could be a "real intermittent" -- for reasons unknown, Javascript -> Java messages do get lost.
For some context, I based this test on an existing test:
http://mxr.mozilla.org/mozilla-central/source/toolkit/components/search/tests/xpcshell/test_purpose.js

But I copied Nick's use of add_task, instead of run_test. I can change that. No idea if it will make a difference or not.
Attached patch patch to use run_test (obsolete) — Splinter Review
This is a simple patch to switch to using run_test instead of add_task.

Try runs are here:
https://tbpl.mozilla.org/?tree=Try&rev=b38cb8ae49c7

So far it's looking green. I'll keep retriggering to look for intermittents.
Assignee: nobody → mark.finkle
Attachment #761594 - Flags: review?(nalexander)
I see lots of use of do_test_pending() and do_test_finished(), but
reading robocop_head.js suggests that such use is an abuse of the
internals of how xpcshell launches child processes.  This is the
documented API, and works locally.
Attachment #761594 - Attachment is obsolete: true
Attachment #761594 - Flags: review?(nalexander)
Attachment #761759 - Flags: review?(mark.finkle)
Assignee: mark.finkle → nalexander
Comment on attachment 761759 [details] [diff] [review]
Use add_test in testDeviceSearchEngines. r=mfinkle

This makes me think either way would work:
https://developer.mozilla.org/en-US/docs/Writing_xpcshell-based_unit_tests#Async_tests

Let's consider this cat successfully skinned
Attachment #761759 - Flags: review?(mark.finkle) → review+
Status: NEW → ASSIGNED
Target Milestone: --- → Firefox 24
https://hg.mozilla.org/mozilla-central/rev/3aa27583bd92
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.