Closed Bug 876874 Opened 12 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.