Closed Bug 1094649 Opened 10 years ago Closed 9 years ago

Intermittent testBrowserDiscovery,testEventDispatcher,testFilePicker,testGeckoRequest,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testSimpleDiscovery,testTrackingProtection | GeckoEventExpecter - blockForEvent timeout: Robocop:JS

Categories

(Firefox for Android Graveyard :: General, defect)

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

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1085591

People

(Reporter: cbook, Assigned: gbrown)

References

(
URL
)

Details

(Keywords: intermittent-failure) 

Android 4.2 x86 Emulator mozilla-inbound opt test androidx86-set-4

https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3643783&repo=mozilla-inbound

22:04:00 WARNING - TEST-UNEXPECTED-FAIL | testFilePicker | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
Flags: needinfo?(mark.finkle)
Summary: Intermittent testFilePicker | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testFilePicker,testHomeProvider | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
Summary: Intermittent testFilePicker,testHomeProvider | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testFilePicker,testHomeProvider,testJNI | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
This is probably the top Android S4 failure we hit.
(In reply to TBPL Robot from comment #97)

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/a8fbf61a24be7e90805b8815a674eb3042691687156c73726cf9140bb9bdb668eb0ef02d9b41f094ddd5fa62d8ca1664b77de94b3735603b4ae0fab1481df4b1

12-10 17:42:31.473 I/Robocop ( 2009): EventExpecter: no longer listening for Gecko:Ready
12-10 17:42:31.473 D/Robocop ( 2009): waiting for Robocop:JS
12-10 17:42:31.473 I/Robocop ( 2009): {"action":"log","message":"Registered listener for Robocop:JS","time":1418233351480,"pid":null,"level":"info","source":"robocop","thread":null}
12-10 17:42:31.484 I/Robocop ( 2009): {"action":"log","message":"Loading JavaScript test from http:\/\/mochi.test:8888\/tests\/robocop\/robocop_javascript.html?slug=1418233351487&path=testJNI.js","time":1418233351487,"pid":null,"level":"info","source":"robocop","thread":null}
12-10 17:42:31.494 I/GeckoConsole( 2009): Locale:OS: en-US
12-10 17:42:31.494 I/GeckoConsole( 2009): New OS locale.
12-10 17:42:31.494 I/GeckoConsole( 2009): Default intl.accept_languages = en-US, en
12-10 17:42:31.494 I/GeckoConsole( 2009): Setting intl.accept_languages to en-us,en
12-10 17:42:31.554 D/dalvikvm( 2009): GC_CONCURRENT freed 764K, 14% free 5281K/6072K, paused 3ms+0ms, total 9ms
12-10 17:42:31.554 D/GeckoHealthRec( 2009): Got all add-ons and prefs.
12-10 17:42:31.554 I/GeckoHealthRec( 2009): Persisting 3 add-ons.
12-10 17:42:31.554 I/GeckoHealthRec( 2009): Persisting prefs.
12-10 17:42:31.554 D/GeckoHealthRec( 2009): Incorporating environment: extensions.blocklist.enabled
12-10 17:42:31.554 D/GeckoHealthRec( 2009): Incorporating environment: intl.accept_languages
12-10 17:42:31.554 D/GeckoHealthRec( 2009): Incorporating environment: toolkit.telemetry.enabled
12-10 17:42:31.564 D/GeckoHealthRec( 2009): Done initializing profile cache. Beginning storage init.
12-10 17:42:31.595 I/GeckoLogger( 2009): fennec :: HealthReportStorage :: Initializing measurement org.mozilla.appSessions to 4 (current 0)
12-10 17:42:31.595 I/GeckoLogger( 2009): fennec :: HealthReportStorage :: Measurement org.mozilla.appSessions now at 4
12-10 17:42:31.595 I/GeckoLogger( 2009): fennec :: HealthReportStorage :: Initializing measurement org.mozilla.searches.counts to 6 (current 0)
12-10 17:42:31.604 I/GeckoLogger( 2009): fennec :: HealthReportStorage :: Measurement org.mozilla.searches.counts now at 6
12-10 17:42:31.604 D/GeckoHealthRec( 2009): Ensuring environment.
12-10 17:42:31.604 D/dalvikvm( 2009): Trying to load lib /data/app-lib/org.mozilla.fennec-1/libmozglue.so 0xb31804d0
12-10 17:42:31.604 D/dalvikvm( 2009): Shared lib '/data/app-lib/org.mozilla.fennec-1/libmozglue.so' already loaded in same CL 0xb31804d0
12-10 17:42:31.604 D/GeckoHealthRec( 2009): Finishing init.
12-10 17:42:31.614 D/GeckoHealthRec( 2009): Checking for orphan session.
12-10 17:42:31.614 D/GeckoIdleService( 2009): Registering Idle observer callback
12-10 17:42:31.614 D/GeckoIdleService( 2009): Register idle observer 0x9b1f5f40 for 180 seconds
12-10 17:42:31.614 D/GeckoIdleService( 2009): Register: adjusting next switch from -1 to 180 seconds
12-10 17:42:31.614 D/GeckoIdleService( 2009): next timeout 180000 msec from now
12-10 17:42:31.614 D/GeckoIdleService( 2009): SetTimerExpiryIfBefore: next timeout 180000 msec from now
12-10 17:42:31.614 D/GeckoIdleService( 2009): reset timer expiry to 180009 msec from now
12-10 17:42:31.614 I/GeckoConsole( 2009): Sending snapshot message.
12-10 17:42:53.644 D/dalvikvm( 1702): GC_CONCURRENT freed 383K, 9% free 4216K/4628K, paused 10ms+1ms, total 17ms
12-10 17:43:08.664 I/Process ( 1592): Sending signal. PID: 1592 SIG: 9
12-10 17:43:08.684 I/ActivityManager( 1203): Process com.android.providers.calendar (pid 1592) has died.
12-10 17:43:08.693 I/GeckoAxis( 2009): Prefs: 0.85,0.97,10.0,0.04,0.04,0.3,0.5
12-10 17:43:08.703 I/GeckoAxis( 2009): Prefs: 0.85,0.97,10.0,0.04,0.04,0.3,0.5
12-10 17:43:08.703 D/dalvikvm( 1203): GC_CONCURRENT freed 694K, 31% free 7091K/10212K, paused 11ms+1ms, total 34ms
12-10 17:43:08.724 D/dalvikvm( 2009): GC_CONCURRENT freed 249K, 11% free 5417K/6072K, paused 4ms+1ms, total 8ms
12-10 17:43:08.724 D/GeckoActivityChooserModel( 2009): Running post-distribution task: quickshare.
12-10 17:43:08.724 E/GeckoApp( 2009): An error occurred during restore
12-10 17:43:08.724 E/GeckoApp( 2009): org.mozilla.gecko.GeckoApp$SessionRestoreException: Could not read from session file
12-10 17:43:08.724 E/GeckoApp( 2009): 	at org.mozilla.gecko.GeckoApp.restoreSessionTabs(GeckoApp.java:1645)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at org.mozilla.gecko.GeckoApp.onWindowFocusChanged(GeckoApp.java:1952)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at org.mozilla.gecko.BrowserApp.onWindowFocusChanged(BrowserApp.java:833)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at com.android.internal.policy.impl.PhoneWindow$DecorView.onWindowFocusChanged(PhoneWindow.java:2451)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at android.view.View.dispatchWindowFocusChanged(View.java:7433)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at android.view.ViewGroup.dispatchWindowFocusChanged(ViewGroup.java:930)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at android.view.ViewRootImpl$ViewRootHandler.handleMessage(ViewRootImpl.java:2927)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at android.os.Handler.dispatchMessage(Handler.java:99)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at android.os.Looper.loop(Looper.java:137)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at android.app.ActivityThread.main(ActivityThread.java:5039)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at java.lang.reflect.Method.invokeNative(Native Method)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at java.lang.reflect.Method.invoke(Method.java:511)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:793)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:560)
12-10 17:43:08.724 E/GeckoApp( 2009): 	at dalvik.system.NativeStart.main(Native Method)
12-10 17:43:08.773 D/GeckoTabs( 2009): Setting about: tab favicon inline.
12-10 17:43:08.783 E/SQLiteLog( 2009): (1) no such table: bookmarks
12-10 17:43:08.833 D/dalvikvm( 2009): GC_CONCURRENT freed 331K, 10% free 5475K/6072K, paused 9ms+1ms, total 13ms
12-10 17:43:08.854 W/GeckoConsole( 2009): [JavaScript Warning: "JavaScript 1.7's let blocks are deprecated" {file: "chrome://specialpowers/content/specialpowers.js" line: 27}]
12-10 17:43:08.864 D/GeckoTabs( 2009): handleMessage: Tab:Added
12-10 17:43:08.864 D/GeckoTabs( 2009): handleMessage: Content:StateChange
12-10 17:43:08.884 I/ActivityManager( 1203): Start proc org.mozilla.fennec.UpdateService for service org.mozilla.fennec/org.mozilla.gecko.updater.UpdateService: pid=2064 uid=10046 gids={50046, 3003, 1015, 1006, 1028}
12-10 17:43:08.894 D/GeckoTabs( 2009): handleMessage: Content:LocationChange
12-10 17:43:08.894 D/GeckoTabs( 2009): handleMessage: Content:SecurityChange
12-10 17:43:08.915 D/GeckoToolbar( 2009): onTabChanged: SELECTED
12-10 17:43:08.915 I/GeckoToolbarDisplayLayout( 2009): zerdatime 308922 - Throbber stop
12-10 17:43:08.915 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: SELECTED
12-10 17:43:08.934 D/GeckoTabs( 2009): handleMessage: DOMTitleChanged
12-10 17:43:08.934 D/Telemetry( 2009): StopUISession: awesomescreen.1, reason=null
12-10 17:43:08.934 D/GeckoToolbar( 2009): onTabChanged: MENU_UPDATED
12-10 17:43:08.934 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: MENU_UPDATED
12-10 17:43:08.934 D/GeckoToolbar( 2009): onTabChanged: RESTORED
12-10 17:43:08.944 D/GeckoToolbar( 2009): onTabChanged: MENU_UPDATED
12-10 17:43:08.944 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: MENU_UPDATED
12-10 17:43:08.944 D/GeckoToolbar( 2009): onTabChanged: START
12-10 17:43:08.944 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: START
12-10 17:43:08.944 D/GeckoToolbar( 2009): onTabChanged: MENU_UPDATED
12-10 17:43:08.944 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: MENU_UPDATED
12-10 17:43:08.944 D/GeckoToolbar( 2009): onTabChanged: LOCATION_CHANGE
12-10 17:43:08.944 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: LOCATION_CHANGE
12-10 17:43:08.944 D/GeckoToolbar( 2009): onTabChanged: SECURITY_CHANGE
12-10 17:43:08.944 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: SECURITY_CHANGE
12-10 17:43:08.954 D/GeckoTabs( 2009): handleMessage: DOMContentLoaded
12-10 17:43:08.974 W/TwoWayView( 2009): Inflation setting LayoutParams height to MATCH_PARENT - does not make much sense as the view might change orientation. Falling back to WRAP_CONTENT
12-10 17:43:08.994 D/dalvikvm( 2009): GC_CONCURRENT freed 296K, 9% free 5563K/6072K, paused 10ms+0ms, total 13ms
12-10 17:43:08.994 D/dalvikvm( 2064): GC_CONCURRENT freed 122K, 4% free 4303K/4452K, paused 7ms+0ms, total 10ms
12-10 17:43:09.004 D/GeckoTabs( 2009): handleMessage: Content:PageShow
12-10 17:43:09.004 D/GeckoTabs( 2009): handleMessage: Tab:ViewportMetadata
12-10 17:43:09.004 D/GeckoTabs( 2009): handleMessage: Content:StateChange
12-10 17:43:09.034 D/dalvikvm( 2064): Trying to load lib /data/app-lib/org.mozilla.fennec-1/libmozglue.so 0xb317cd50
12-10 17:43:09.034 D/dalvikvm( 2064): Added shared lib /data/app-lib/org.mozilla.fennec-1/libmozglue.so 0xb317cd50
12-10 17:43:09.034 D/dalvikvm( 2064): No JNI_OnLoad found in /data/app-lib/org.mozilla.fennec-1/libmozglue.so 0xb317cd50, skipping init
12-10 17:43:09.044 E/dalvikvm( 2009): Could not find class 'android.transition.Transition', referenced from method android.support.v4.app.BackStackRecord.captureExitingViews
12-10 17:43:09.044 W/dalvikvm( 2009): VFY: unable to resolve check-cast 1102 (Landroid/transition/Transition;) in Landroid/support/v4/app/BackStackRecord;
12-10 17:43:09.044 D/dalvikvm( 2009): VFY: replacing opcode 0x1f at 0x001d
12-10 17:43:09.044 E/dalvikvm( 2009): Could not find class 'android.transition.Transition', referenced from method android.support.v4.app.BackStackRecord.configureTransitions
12-10 17:43:09.044 W/dalvikvm( 2009): VFY: unable to resolve check-cast 1102 (Landroid/transition/Transition;) in Landroid/support/v4/app/BackStackRecord;
12-10 17:43:09.044 D/dalvikvm( 2009): VFY: replacing opcode 0x1f at 0x00e7
12-10 17:43:09.044 I/dalvikvm( 2009): Could not find method android.view.View.getTransitionName, referenced from method android.support.v4.app.BackStackRecord.setBackNameOverrides
12-10 17:43:09.044 W/dalvikvm( 2009): VFY: unable to resolve virtual method 7577: Landroid/view/View;.getTransitionName ()Ljava/lang/String;
12-10 17:43:09.044 D/dalvikvm( 2009): VFY: replacing opcode 0x6e at 0x0021
12-10 17:43:09.044 I/dalvikvm( 2009): Could not find method android.view.View.getTransitionName, referenced from method android.support.v4.app.BackStackRecord.setNameOverrides
12-10 17:43:09.044 W/dalvikvm( 2009): VFY: unable to resolve virtual method 7577: Landroid/view/View;.getTransitionName ()Ljava/lang/String;
12-10 17:43:09.044 D/dalvikvm( 2009): VFY: replacing opcode 0x6e at 0x0014
12-10 17:43:09.044 D/dalvikvm( 2009): DexOpt: unable to opt direct call 0x1c23 at 0xf2 in Landroid/support/v4/app/BackStackRecord;.configureTransitions
12-10 17:43:09.044 W/dalvikvm( 2009): Unable to resolve superclass of Landroid/support/v4/app/FragmentTransitionCompat21$3; (1101)
12-10 17:43:09.044 W/dalvikvm( 2009): Link of class 'Landroid/support/v4/app/FragmentTransitionCompat21$3;' failed
12-10 17:43:09.044 D/dalvikvm( 2009): DexOpt: unable to opt direct call 0x073a at 0x13e in Landroid/support/v4/app/BackStackRecord;.configureTransitions
12-10 17:43:09.054 D/GeckoToolbar( 2009): onTabChanged: FAVICON
12-10 17:43:09.054 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: FAVICON
12-10 17:43:09.064 I/GeckoHealth( 2009): fennec :: HealthReportBroadcastService :: Registering HealthReportUploadService.
12-10 17:43:09.064 I/GeckoHealth( 2009): fennec :: BackgroundService :: Setting inexact repeating alarm for interval 3600000
12-10 17:43:09.064 D/GeckoToolbar( 2009): onTabChanged: TITLE
12-10 17:43:09.064 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: TITLE
12-10 17:43:09.064 D/GeckoToolbar( 2009): onTabChanged: LOADED
12-10 17:43:09.064 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: LOADED
12-10 17:43:09.085 I/UpdateService( 2064): no update has ever been attempted, checking now
12-10 17:43:09.085 I/UpdateService( 2064): next update will be at: Wed Dec 10 21:43:09 GMT 2014
12-10 17:43:09.085 I/UpdateService( 2064): opening connection with url: https://aus4.mozilla.org/update/4/Fennec/37.0a1/20141210091014/Android_x86-gcc3/en-US/default/4.2/default/default/37.0a1/update.xml
12-10 17:43:09.094 D/dalvikvm( 2064): GC_CONCURRENT freed 178K, 5% free 4517K/4728K, paused 0ms+0ms, total 3ms
12-10 17:43:09.104 D/dalvikvm( 2009): GC_CONCURRENT freed 224K, 6% free 5725K/6072K, paused 6ms+0ms, total 10ms
12-10 17:43:09.104 D/GeckoToolbar( 2009): onTabChanged: PAGE_SHOW
12-10 17:43:09.114 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: PAGE_SHOW
12-10 17:43:09.114 D/GeckoToolbar( 2009): onTabChanged: VIEWPORT_CHANGE
12-10 17:43:09.114 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: VIEWPORT_CHANGE
12-10 17:43:09.164 D/GeckoToolbar( 2009): onTabChanged: STOP
12-10 17:43:09.164 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: STOP
12-10 17:43:09.174 D/GeckoToolbar( 2009): onTabChanged: FAVICON
12-10 17:43:09.174 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: FAVICON
12-10 17:43:09.174 D/GeckoSuggestedSites( 2009): No cached sites, refreshing.
12-10 17:43:09.174 D/GeckoSuggestedSites( 2009): Refreshing suggested sites from file
12-10 17:43:09.174 D/GeckoSuggestedSites( 2009): Running post-distribution task: suggested sites.
12-10 17:43:09.174 D/GeckoSuggestedSites( 2009): Loading blacklisted suggested sites from SharedPreferences.
12-10 17:43:09.174 D/GeckoSuggestedSites( 2009): Number of suggested sites: 4
12-10 17:43:09.234 I/UpdateService( 2064): no update available
12-10 17:43:09.244 D/dalvikvm( 1203): GC_CONCURRENT freed 677K, 31% free 7052K/10212K, paused 0ms+0ms, total 8ms
12-10 17:43:09.334 W/Settings( 2009): Setting airplane_mode_on has moved from android.provider.Settings.System to android.provider.Settings.Global, returning read-only value.
12-10 17:43:09.524 D/GeckoToolbar( 2009): onTabChanged: THUMBNAIL
12-10 17:43:09.524 D/GeckoBrowserApp( 2009): BrowserApp.onTabChanged: 0: THUMBNAIL
12-10 17:43:10.014 D/dalvikvm( 2009): GC_CONCURRENT freed 253K, 5% free 5915K/6192K, paused 0ms+11ms, total 12ms
...
12-10 17:43:30.764 I/GeckoConsole( 2009): 1418233410765	addons.update-checker	WARN	Request failed: http://10.0.2.2:8858/extensions-dummy/updateBackgroundURL - 404: Not Found
12-10 17:43:30.764 I/Gecko   ( 2009): 1418233410765	addons.update-checker	WARN	Request failed: http://10.0.2.2:8858/extensions-dummy/updateBackgroundURL - 404: Not Found
12-10 17:43:30.764 I/GeckoConsole( 2009): 1418233410769	addons.update-checker	WARN	Request failed: http://10.0.2.2:8858/extensions-dummy/updateBackgroundURL - 404: Not Found
12-10 17:43:30.764 I/Gecko   ( 2009): 1418233410769	addons.update-checker	WARN	Request failed: http://10.0.2.2:8858/extensions-dummy/updateBackgroundURL - 404: Not Found
12-10 17:43:30.764 I/GeckoConsole( 2009): 1418233410772	addons.update-checker	WARN	Request failed: http://10.0.2.2:8858/extensions-dummy/updateBackgroundURL - 404: Not Found
12-10 17:43:30.764 I/Gecko   ( 2009): 1418233410772	addons.update-checker	WARN	Request failed: http://10.0.2.2:8858/extensions-dummy/updateBackgroundURL - 404: Not Found
...
12-10 17:45:31.496 E/Robocop ( 2009): Dumping ALL the threads!
12-10 17:45:31.496 E/Robocop ( 2009): Thread[Picasso-Idle,5,main]
...
Summary: Intermittent testFilePicker,testHomeProvider,testJNI | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testFilePicker,testHistoryService,testHomeProvider,testJNI | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
Try run that reproduced the error in testJNI: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=b0c7426b3631. It looks to me like testJNI.js is not loaded (or at least not run) -- I can't think of an explanation.
Very nearly all of the recent failures are Android x86.

Very nearly all of the recent failures are testHomeProvider or testHistoryService.

testHomeProvider is the first robocop test in the x86 robocop-2 chunk.
testHistoryService is the first robocop test in the x86 robocop-3 chunk.
(In reply to Geoff Brown [:gbrown] from comment #106)
> Try run that reproduced the error in testJNI:
> https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=b0c7426b3631. It
> looks to me like testJNI.js is not loaded (or at least not run) -- I can't
> think of an explanation.

It's the same story for testHomeProvider and testHistoryService failures -- the test file is not loaded.

These tests call Tabs.loadUrl to load the .js test file. In the failure cases, Tabs.loadUrl is called, Tab:Load is sent, Tab:Load is received in browser.js, loadURI is called, but with aBrowser == null, causing a hasty return with no complaint:

  http://hg.mozilla.org/mozilla-central/annotate/5438e3f74848/mobile/android/chrome/content/browser.js#l1029
I also verified that, in the failure case, browser == null in browser.js' observe function, when Tab:Load is observed.
On irc, mfinkle noted:

01-19 23:58:05.594 W/GeckoTabs( 2008): Tabs.loadUrl sends Tab:Load with {"parentId":-1,"selected":true,"delayLoad":false,"isPrivate":false,"pinned":false,"desktopMode":false,"newTab":false,"userEntered":false,"url":"http:\/\/mochi.test:8888\/tests\/robocop\/robocop_javascript.html?slug=1421711885602&path=testHistoryService.js"}

we are supposed to use the selected tab, which is null. I'll try waiting for delayed start to see if that helps avoid this condition.
See Also: → 1088708
Summary: Intermittent testFilePicker,testHistoryService,testHomeProvider,testJNI | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testFilePicker,testHistoryService,testHomeProvider,testJNI,testNetworkManager | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
(In reply to Geoff Brown [:gbrown] from comment #319)
> I'll try waiting for delayed start to see if that helps avoid this condition.

I tried changing JavascriptTest's blockForGeckoReady to blockForDelayedStartup. That caused a frequent failure on x86 just like bug 1088708: time out waiting for Gecko:DelayedStartup because the event is sent before the test starts.

I tried a modified wait for Gecko:DelayedStartup at https://treeherder.mozilla.org/#/jobs?repo=try&revision=6ced3ef0418d. Again, on x86, Gecko:DelayedStartup is rarely received, but we wait for 30 seconds after Gecko:Ready and then continue with the test. In these logs, it looks like startup is quite complete, but JavascriptTests still intermittently fail on Robocop:JS, and it still seems to be because browser is null when Tab:Load is observed.
Flags: needinfo?(mark.finkle)
See Also: → 1091955
Summary: Intermittent testFilePicker,testHistoryService,testHomeProvider,testJNI,testNetworkManager | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testFilePicker,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testGeckoRequest | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
Summary: Intermittent testFilePicker,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testGeckoRequest | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testFilePicker,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testGeckoRequest,testTrackingProtection | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
rackingProtection is looking pretty frequent on 4.3 since being enabled in production.
Flags: needinfo?(gbrown)
Epic copy/paste there - "testTrackingProtection"
In the testTrackingProtection logcats I noticed:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/70b257a908267e09732e19591e9984e8845ca379b512b4f7a000dc9b5642392eb12186b5f14762f2ddd33293e1155bfd5499c395bbc1c0bb6928db9c06727f1a

04-23 16:18:00.749 W/GeckoConsole(  786): [JavaScript Error: "TypeError: dump is not a function" {file: "robocop_head.js" line: 27}]
04-23 16:18:00.779 W/GeckoConsole(  786): [JavaScript Error: "TypeError: dump is not a function" {file: "robocop_head.js" line: 27}]

Nick -- do you know what has happened here?
Flags: needinfo?(nalexander)
Summary: Intermittent testFilePicker,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testGeckoRequest,testTrackingProtection | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testBrowserDiscovery,testFilePicker,testGeckoRequest,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testTrackingProtection | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
(In reply to Geoff Brown [:gbrown] from comment #386)
> In the testTrackingProtection logcats I noticed:
> 
> http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/
> 70b257a908267e09732e19591e9984e8845ca379b512b4f7a000dc9b5642392eb12186b5f1476
> 2f2ddd33293e1155bfd5499c395bbc1c0bb6928db9c06727f1a
> 
> 04-23 16:18:00.749 W/GeckoConsole(  786): [JavaScript Error: "TypeError:
> dump is not a function" {file: "robocop_head.js" line: 27}]
> 04-23 16:18:00.779 W/GeckoConsole(  786): [JavaScript Error: "TypeError:
> dump is not a function" {file: "robocop_head.js" line: 27}]
> 
> Nick -- do you know what has happened here?

Well, sort of.  If you look at https://dxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/robocop_testharness.js#41, you'll see that we evaluate robocop_head.js in a particular JavaScript environment (testScope).  That scope has dump defined to do a funky thing.  In some way, we're seeing that scope missing dump.  My naive expectation is that we're seeing an earlier JavaScript execution error that maybe stops something executing at all.  I'll try to look at the logs but it's hard to say what's really up.
Flags: needinfo?(nalexander)
Depends on: 1158363
Depends on: 1158384
Summary: Intermittent testBrowserDiscovery,testFilePicker,testGeckoRequest,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testTrackingProtection | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testBrowserDiscovery,testFilePicker,testGeckoRequest,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testSimpleDiscovery,testTrackingProtection | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
Logcats for Comment 406 and Comment 407 both show "Exception handling message "Gecko:Ready"" -- bug 1158309. It is not obvious that this is the cause of the test failures, but logcats for successful testSimpleDiscovery runs on 4.3 do not show that exception.
Depends on: 1158309
Summary: Intermittent testBrowserDiscovery,testFilePicker,testGeckoRequest,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testSimpleDiscovery,testTrackingProtection | GeckoEventExpecter - blockForEvent timeout: Robocop:JS → Intermittent testBrowserDiscovery,testEventDispatcher,testFilePicker,testGeckoRequest,testHistoryService,testHomeProvider,testJNI,testNetworkManager,testSimpleDiscovery,testTrackingProtection | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
With testTrackingProtection and testBrowserDiscovery skipped, frequency of this bug is greatly reduced.
Flags: needinfo?(gbrown)
See Also: → 1160008
Note that a fix for bug 1085591 landed on mozilla-central at 2015-07-03 03:11:29 PDT. All failures since have been on aurora.
Assignee: nobody → gbrown
I'm convinced that all recent failures here were caused by bug 1085591 (onWindowFocusChanged not always called).

All sorts of hangs could produce this generic "GeckoEventExpecter - blockForEvent timeout: Robocop:JS" message in future...when that happens, we should open a new bug.
Status: NEW → RESOLVED
Closed: 9 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.