Closed Bug 876874 Opened 11 years ago Closed 11 years ago

Intermittent testDistribution | GeckoEventExpecter - blockForEvent timeout: Preferences:Data

Categories

(Firefox for Android Graveyard :: General, defect)

Product:
Firefox for Android Graveyard
Component:
General
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 896199

People

(Reporter: RyanVM, Assigned: gbrown)

References

Details

(Keywords: intermittent-failure) 

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

Android Armv6 Tegra 250 mozilla-inbound opt test robocop-2 on 2013-05-28 12:17:56 PDT for push f6d827971b26
slave: tegra-170

0 INFO SimpleTest START
1 INFO TEST-START | testDistribution
Dumping ALL the threads!
Thread[JDWP,5,system]
dalvik.system.NativeStart.run(Native Method)

Thread[HeapWorker,5,system]
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:319)
org.mozilla.gecko.GeckoThread.run(GeckoThread.java:113)

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.testDistribution.setTestLocale(testDistribution.java:190)
org.mozilla.fennec.tests.testDistribution.testDistribution(testDistribution.java:48)
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:129)
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[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[Binder Thread #1,5,main]
dalvik.system.NativeStart.run(Native Method)

Thread[Binder Thread #2,5,main]
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[Compiler,5,system]
dalvik.system.NativeStart.run(Native Method)

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

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[RefQueueWorker@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@484ca810,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[Signal Catcher,5,system]
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)


2 INFO TEST-UNEXPECTED-FAIL | testDistribution | GeckoEventExpecter - blockForEvent timeout: Preferences:Data
Exception caught during test!
junit.framework.AssertionFailedError: 2 INFO TEST-UNEXPECTED-FAIL | testDistribution | GeckoEventExpecter - blockForEvent timeout: Preferences:Data
	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.testDistribution.setTestLocale(testDistribution.java:190)
	at org.mozilla.fennec.tests.testDistribution.testDistribution(testDistribution.java:48)
	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:129)
	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)
3 INFO TEST-UNEXPECTED-FAIL | testDistribution | Exception caught - junit.framework.AssertionFailedError: 2 INFO TEST-UNEXPECTED-FAIL | testDistribution | GeckoEventExpecter - blockForEvent timeout: Preferences:Data
4 INFO TEST-PASS | testDistribution | clean up mock package - deleted /data/data/org.mozilla.fennec/mock-package.zip
5 INFO TEST-UNEXPECTED-FAIL | testDistribution | clean up distribution files - deleted /data/data/org.mozilla.fennec/distribution
INFO | automation.py | Application ran for: 0:01:59.817078
INFO | zombiecheck | Reading PID log: /tmp/tmpp4wFybpidlog
/data/anr/traces.txt not found
WARNING | leakcheck | refcount logging is off, so leaks can't be detected!

INFO | runtests.py | Running tests: end.
Summary: Intermittent testDistribution | GeckoEventExpecter - blockForEvent timeout: Distribution:Set:OK → Intermittent testDistribution | GeckoEventExpecter - blockForEvent timeout: Preferences:Data
This seems to be very low frequency -- difficult to reproduce and debug.

I see no sign of deadlock in these traces. 

The failure happens in setTestLocale(), which sends Preferences:Set on general.useragent.locale, then waits for Preferences:Data and sends Preferences:Get. Several Preferences:Data's are received, but apparently not the expected one. The test code looks fine. This is happening during startup (no wait for Gecko:Ready in this test) -- I wonder if that is a factor.
Try run here with additional logging: https://tbpl.mozilla.org/?tree=Try&rev=24c76ce519b0.

setTestLocale normally sees:
{"type":"Preferences:Data","requestId":"1","preferences":[{"type":"string","value":"0","name":"browser.chrome.titlebarMode"}]}
{"type":"Preferences:Data","requestId":"2","preferences":[{"type":"bool","value":false,"name":"browser.chrome.dynamictoolbar"}]}
{"type":"Preferences:Data","requestId":"3","preferences":[{"type":"string","value":"","name":"app.orientation.default"}]}
{"type":"Preferences:Data","requestId":"4","preferences":[{"type":"string","value":"standard","name":"ui.scrolling.axis_lock_mode"}]}
{"type":"Preferences:Data","requestId":"5","preferences":[{"type":"int","value":-1,"name":"ui.scrolling.friction_fast"},{"type":"int","value":-1,"name":"ui.scrolling.friction_slow"},{"type":"int","value":-1,"name":"ui.scrolling.max_event_acceleration"},{"type":"int","value":-1,"name":"ui.scrolling.overscroll_decel_rate"},{"type":"int","value":-1,"name":"ui.scrolling.overscroll_snap_limit"},{"type":"int","value":-1,"name":"ui.scrolling.min_scrollable_distance"}]}
{"type":"Preferences:Data","requestId":"6","preferences":[{"type":"int","value":20,"name":"browser.ui.show-margins-threshold"}]}
{"type":"Preferences:Data","requestId":"7","preferences":[{"type":"bool","value":true,"name":"toolkit.telemetry.enabledPreRelease"},{"type":"bool","value":true,"name":"extensions.blocklist.enabled"}]}
{"type":"Preferences:Data","requestId":"8","preferences":[{"type":"string","value":"wifi","name":"app.update.autodownload"}]}
{"type":"Preferences:Data","requestId":"9","preferences":[{"type":"int","value":0,"name":"app.geo.reportdata"}]}
{"type":"Preferences:Data","requestId":"testDistribution","preferences":[{"type":"string","value":"en-US","name":"general.useragent.locale"}]}

but in the failing case:

{"type":"Preferences:Data","requestId":"1","preferences":[{"type":"string","value":"0","name":"browser.chrome.titlebarMode"}]}
{"type":"Preferences:Data","requestId":"2","preferences":[{"type":"bool","value":false,"name":"browser.chrome.dynamictoolbar"}]}
{"type":"Preferences:Data","requestId":"3","preferences":[{"type":"string","value":"","name":"app.orientation.default"}]}
{"type":"Preferences:Data","requestId":"4","preferences":[{"type":"bool","value":true,"name":"toolkit.telemetry.enabledPreRelease"},{"type":"bool","value":true,"name":"extensions.blocklist.enabled"}]}
{"type":"Preferences:Data","requestId":"6","preferences":[{"type":"int","value":-1,"name":"ui.scrolling.friction_fast"},{"type":"int","value":-1,"name":"ui.scrolling.friction_slow"},{"type":"int","value":-1,"name":"ui.scrolling.max_event_acceleration"},{"type":"int","value":-1,"name":"ui.scrolling.overscroll_decel_rate"},{"type":"int","value":-1,"name":"ui.scrolling.overscroll_snap_limit"},{"type":"int","value":-1,"name":"ui.scrolling.min_scrollable_distance"}]}
{"type":"Preferences:Data","requestId":"7","preferences":[{"type":"int","value":20,"name":"browser.ui.show-margins-threshold"}]}
{"type":"Preferences:Data","requestId":"10","preferences":[{"type":"bool","value":false,"name":"gfx.android.rgb16.force"}]}
{"type":"Preferences:Data","requestId":"11","preferences":[{"type":"int","value":1,"name":"gfx.displayport.strategy"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_fm.multiplier"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_fm.danger_x"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_fm.danger_y"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_vb.multiplier"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_vb.threshold"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_vb.reverse_buffer"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_vb.danger_x_base"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_vb.danger_y_base"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_vb.danger_x_incr"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_vb.danger_y_incr"},{"type":"int","value":-1,"name":"gfx.displayport.strategy_pb.threshold"}]}

:margaret -- Any idea why that might happen?
Flags: needinfo?(margaret.leibovic)
Assignee: nobody → gbrown
Depends on: 896199
Flags: needinfo?(margaret.leibovic)
All of these failures that I investigated were caused by bug 896199.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → DUPLICATE
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.