Closed Bug 1772518 Opened 4 years ago Closed 4 years ago

Intermittent org.mozilla.geckoview.test.SelectionActionDelegateTest#selectAll[#text] | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms

Categories

(GeckoView :: General, defect, P5)

Product:
GeckoView
Component:
General
Platform:
Unspecified
All
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=380137084&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/HomfE4NBT-6EyEMSxd8Lhw/runs/0/artifacts/public/logs/live_backing.log

[task 2022-06-03T10:57:56.393Z] 10:57:56     INFO -  TEST-START | org.mozilla.geckoview.test.SelectionActionDelegateTest#selectAll[#text]
[task 2022-06-03T10:58:29.188Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=925
[task 2022-06-03T10:58:29.188Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2022-06-03T10:58:29.189Z] 10:58:29     INFO -  org.mozilla.geckoview.test | Error in selectAll[#text](org.mozilla.geckoview.test.SelectionActionDelegateTest):
[task 2022-06-03T10:58:29.189Z] 10:58:29     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1775)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1531)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1506)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:186)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.testThat(SelectionActionDelegateTest.kt:271)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.selectAll(SelectionActionDelegateTest.kt:185)
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test |
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=selectAll[#text]
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SelectionActionDelegateTest
[task 2022-06-03T10:58:29.190Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1775)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1531)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1506)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:186)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.testThat(SelectionActionDelegateTest.kt:271)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.selectAll(SelectionActionDelegateTest.kt:185)
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test |
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=556
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2022-06-03T10:58:29.192Z] 10:58:29     INFO -  Printing logcat for test:
[task 2022-06-03T10:58:29.269Z] 10:58:29     INFO -  06-03 10:57:55.787 E/GeckoSessionTestRule( 3429): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec selectAll[#text](org.mozilla.geckoview.test.SelectionActionDelegateTest)
[task 2022-06-03T10:58:29.269Z] 10:58:29     INFO -  06-03 10:57:55.787 E/GeckoSessionTestRule( 3429): before prepareStatement selectAll[#text](org.mozilla.geckoview.test.SelectionActionDelegateTest)
[task 2022-06-03T10:58:29.271Z] 10:58:29     INFO -  06-03 10:57:55.795 D/EGL_emulation( 3429): eglMakeCurrent: 0x7860bb71b6c0: ver 3 0 (tinfo 0x7860bb717980)
[task 2022-06-03T10:58:29.271Z] 10:58:29     INFO -  06-03 10:57:55.796 D/EGL_emulation( 2118): eglMakeCurrent: 0x7860e0e746a0: ver 3 0 (tinfo 0x7860e0e8fa20)
[task 2022-06-03T10:58:29.271Z] 10:58:29     INFO -  06-03 10:57:55.803 I/WindowManager( 1657): Destroying surface Surface(name=com.android.launcher3/com.android.launcher3.Launcher) called by com.android.server.wm.WindowStateAnimator.destroySurface:2014 com.android.server.wm.WindowStateAnimator.destroySurfaceLocked:881 com.android.server.wm.WindowState.destroyOrSaveSurface:2073 com.android.server.wm.WindowManagerService.tryStartExitingAnimation:3017 com.android.server.wm.WindowManagerService.relayoutWindow:2897 com.android.server.wm.Session.relayout:215 android.view.IWindowSession$Stub.onTransact:286 com.android.server.wm.Session.onTransact:136
[task 2022-06-03T10:58:29.271Z] 10:58:29     INFO -  06-03 10:57:55.816 I/ActivityManager( 1657): Displayed org.mozilla.geckoview.test/.GeckoViewTestActivity: +96ms (total +140ms)
[task 2022-06-03T10:58:29.271Z] 10:58:29     INFO -  06-03 10:57:55.837 D/LifecycleMonitor( 3429): Lifecycle status change: androidx.test.core.app.InstrumentationActivityInvoker$BootstrapActivity@393035f in: STOPPED
[task 2022-06-03T10:58:29.271Z] 10:58:29     INFO -  06-03 10:57:55.837 V/ActivityScenario( 3429): Activity lifecycle changed event received but ignored because the intent does not match. startActivityIntent=Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] cmp=org.mozilla.geckoview.test/.GeckoViewTestActivity }, activity.getIntent()=Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10008000 cmp=org.mozilla.geckoview.test/androidx.test.core.app.InstrumentationActivityInvoker$BootstrapActivity (has extras) }, activity=androidx.test.core.app.InstrumentationActivityInvoker$BootstrapActivity@393035f
[task 2022-06-03T10:58:29.271Z] 10:58:29     INFO -  06-03 10:57:56.011 I/WindowManager( 1657): Destroying surface Surface(name=Starting org.mozilla.geckoview.test) called by com.android.server.wm.WindowStateAnimator.destroySurface:2014 com.android.server.wm.WindowStateAnimator.destroySurfaceLocked:881 com.android.server.wm.WindowState.destroyOrSaveSurface:2073 com.android.server.wm.AppWindowToken.destroySurfaces:363 com.android.server.wm.WindowStateAnimator.finishExit:565 com.android.server.wm.WindowStateAnimator.stepAnimationLocked:491 com.android.server.wm.WindowAnimator.updateWindowsLocked:303 com.android.server.wm.WindowAnimator.animateLocked:704
[task 2022-06-03T10:58:29.271Z] 10:58:29     INFO -  06-03 10:57:57.753 D/GeckoViewStartup( 3429): onEvent GeckoView:StorageDelegate:Attached
[task 2022-06-03T10:58:29.272Z] 10:58:29     INFO -  06-03 10:57:57.755 D/ServiceAllocator( 3429): org.mozilla.gecko.process.GeckoChildProcessServices$tab36 updateBindings: IDLE priority, 6 importance, 0 successful binds, 0 failed binds, 2 successful unbinds
[task 2022-06-03T10:58:29.272Z] 10:58:29     INFO -  06-03 10:57:57.773 D/GeckoViewNavigation( 3429): sessionContextId=null
[task 2022-06-03T10:58:29.272Z] 10:58:29     INFO -  06-03 10:57:57.778 D/ServiceAllocator( 3429): org.mozilla.gecko.process.GeckoChildProcessServices$tab36 updateBindings: FOREGROUND priority, 2 importance, 2 successful binds, 0 failed binds, 0 successful unbinds
[task 2022-06-03T10:58:29.272Z] 10:58:29     INFO -  06-03 10:57:57.780 E/eglCodecCommon(24641): glUtilsParamSize: unknow param 0x00008caa
[task 2022-06-03T10:58:29.272Z] 10:58:29     INFO -  06-03 10:57:57.790 E/eglCodecCommon(24641): glUtilsParamSize: unknow param 0x00008741
[task 2022-06-03T10:58:29.272Z] 10:58:29     INFO -  06-03 10:57:57.796 D/GeckoViewModule( 3429): registerListener ["GeckoViewContent:ExitFullScreen","GeckoView:ClearMatches","GeckoView:DisplayMatches","GeckoView:FindInPage","GeckoView:RestoreState","GeckoView:ScrollBy","GeckoView:ScrollTo","GeckoView:SetActive","GeckoView:SetFocused","GeckoView:SetPriorityHint","GeckoView:UpdateInitData","GeckoView:ZoomToInput"]
[task 2022-06-03T10:58:29.272Z] 10:58:29     INFO -  06-03 10:57:57.797 D/GeckoViewNavigation( 3429): onInit
[task 2022-06-03T10:58:29.273Z] 10:58:29     INFO -  06-03 10:57:57.797 D/GeckoViewModule( 3429): registerListener ["GeckoView:GoBack","GeckoView:GoForward","GeckoView:GotoHistoryIndex","GeckoView:LoadUri","GeckoView:Reload","GeckoView:Stop","GeckoView:PurgeHistory"]
[task 2022-06-03T10:58:29.273Z] 10:58:29     INFO -  06-03 10:57:57.797 D/GeckoViewNavigation( 3429): onEnable
[task 2022-06-03T10:58:29.273Z] 10:58:29     INFO -  06-03 10:57:57.797 D/GeckoViewProcessHangMonitor( 3429): onInit
[task 2022-06-03T10:58:29.273Z] 10:58:29     INFO -  06-03 10:57:57.797 D/GeckoViewProcessHangMonitor( 3429): onEnable
[task 2022-06-03T10:58:29.273Z] 10:58:29     INFO -  06-03 10:57:57.797 D/GeckoViewModule( 3429): registerListener ["GeckoView:HangReportStop","GeckoView:HangReportWait"]
[task 2022-06-03T10:58:29.273Z] 10:58:29     INFO -  06-03 10:57:57.798 D/GeckoViewSelectionActionDelegate[C](22200): handleEvent: visibilitychange
[task 2022-06-03T10:58:29.273Z] 10:58:29     INFO -  06-03 10:57:57.798 D/GeckoViewProgress( 3429): onEnable
[task 2022-06-03T10:58:29.274Z] 10:58:29     INFO -  06-03 10:57:57.798 D/GeckoViewModule( 3429): registerListener GeckoView:FlushSessionState
[task 2022-06-03T10:58:29.274Z] 10:58:29     INFO -  06-03 10:57:57.799 D/GeckoViewSelectionAction( 3429): onEnable
[task 2022-06-03T10:58:29.274Z] 10:58:29     INFO -  06-03 10:57:57.799 D/GeckoViewModule( 3429): registerListener ["GeckoView:ExecuteSelectionAction"]
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.799 D/GeckoViewSettings( 3429): onInit
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.799 D/GeckoViewModule( 3429): registerListener ["GeckoView:GetUserAgent"]
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.799 D/GeckoViewSettings( 3429): onSettingsUpdate: {"chromeUri":null,"screenId":0,"userAgentOverride":null,"allowJavascript":true,"userAgentMode":0,"viewportMode":0,"useTrackingProtection":false,"suspendMediaWhenInactive":false,"usePrivateMode":false,"unsafeSessionContextId":null,"displayMode":0,"sessionContextId":null,"fullAccessibilityTree":false,"isPopup":false}
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.800 D/GeckoViewModule( 3429): registerListener ["GeckoView:WebExtension:SetTabActive"]
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.800 D/GeckoViewModule( 3429): registerListener ["ContentBlocking:RequestLog"]
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.801 D/GeckoViewMediaControl( 3429): onEnable
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.801 D/GeckoViewSettings[C](22200): receiveMessage: SettingsUpdate
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.801 D/GeckoViewModule( 3429): registerListener ["GeckoView:MediaSession:Play","GeckoView:MediaSession:Pause","GeckoView:MediaSession:Stop","GeckoView:MediaSession:NextTrack","GeckoView:MediaSession:PrevTrack","GeckoView:MediaSession:SeekForward","GeckoView:MediaSession:SeekBackward","GeckoView:MediaSession:SkipAd","GeckoView:MediaSession:SeekTo","GeckoView:MediaSession:MuteAudio"]
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.802 I/GeckoSession( 3429): zerdatime 435924 - chrome startup finished
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.806 W/GeckoEditableChild(22200): No editable parent
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.807 D/GeckoViewXUL( 3429): receiveMessage GeckoView:ContentModuleLoaded {}
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.809 D/EGL_emulation(24641): eglMakeCurrent: 0x7860e8c7bb80: ver 3 0 (tinfo 0x7860e8cb4b20)
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.809 D/GeckoSession( 3429): handleMessage GeckoView:PageStart uri=about:blank
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.809 E/GeckoSessionTestRule( 3429): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStart(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.810 D/GeckoSession( 3429): handleMessage GeckoView:LocationChange uri=about:blank
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.810 E/GeckoSessionTestRule( 3429): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String,java.util.List)
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.810 E/GeckoSessionTestRule( 3429): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoBack(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.810 E/GeckoSessionTestRule( 3429): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoForward(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.810 D/GeckoSession( 3429): handleMessage GeckoView:PageStop uri=null
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.810 E/GeckoSessionTestRule( 3429): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStop(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.810 E/GeckoSessionTestRule( 3429): after prepareStatement
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.811 D/GeckoViewModule( 3429): dispatch GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/inputs.html","flags":0,"headerFilter":1}
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.811 D/GeckoViewNavigation( 3429): onEvent: event=GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/inputs.html","flags":0,"headerFilter":1}
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.813 E/eglCodecCommon(24641): glUtilsParamSize: unknow param 0x00008caa
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.817 D/GeckoViewProgress( 3429): ProgressTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.817 D/GeckoViewProgress( 3429): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/inputs.html
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.817 D/GeckoViewProgress( 3429): ProgressTracker start http://localhost:4245/assets/www/inputs.html
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.817 D/GeckoViewProgress( 3429): ProgressTracker updateProgress
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.817 D/GeckoViewProgress( 3429): ProgressTracker updateProgress data={"prev":0,"uri":"http://localhost:4245/assets/www/inputs.html","locationChange":false,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":false} progress=15
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.818 D/GeckoSession( 3429): handleMessage GeckoView:ProgressChanged uri=null
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.818 D/GeckoViewProgress( 3429): StateTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK loadType=1
[task 2022-06-03T10:58:29.278Z] 10:58:29     INFO -  06-03 10:57:57.818 D/GeckoSession( 3429): handleMessage GeckoView:PageStart uri=http://localhost:4245/assets/www/inputs.html
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.827 I/art     (24778): Late-enabling -Xcheck:jni
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.828 W/art     (24778): Unexpected CPU variant for X86 using defaults: x86_64
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.832 I/ActivityManager( 1657): Start proc 24778:org.mozilla.geckoview.test:tab29/u0a62 for service org.mozilla.geckoview.test/org.mozilla.gecko.process.GeckoChildProcessServices$tab29
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.834 D/ServiceAllocator( 3429): org.mozilla.gecko.process.GeckoChildProcessServices$tab29 updateBindings: FOREGROUND priority, 0 importance, 3 successful binds, 0 failed binds, 0 successful unbinds
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.844 I/MultiDex(24778): VM with version 2.1.0 has multidex support
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.844 I/MultiDex(24778): Installing application
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.844 I/MultiDex(24778): VM has multidex support, MultiDex support library is disabled.
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.846 I/ServiceChildProcess(24778): onCreate
[task 2022-06-03T10:58:29.279Z] 10:58:29     INFO -  06-03 10:57:57.847 D/GeckoThread(24778): State changed to LAUNCHED
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.848 I/GeckoThread(24778): preparing to run Gecko
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.852 D/ServiceAllocator( 3429): org.mozilla.gecko.process.GeckoChildProcessServices$tab29 updateBindings: FOREGROUND priority, 2 importance, 0 successful binds, 0 failed binds, 0 successful unbinds
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.853 D/GeckoViewXUL( 3429): WillChangeBrowserRemoteness
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.854 D/GeckoThread(24778): State changed to MOZGLUE_READY
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.854 I/GeckoLoader(24778): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.855 I/GeckoLoader(24778): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.855 E/GeckoLibLoad(24778): Load sqlite start
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.855 D/GeckoViewSelectionActionDelegate[C](22200): handleEvent: visibilitychange
[task 2022-06-03T10:58:29.280Z] 10:58:29     INFO -  06-03 10:57:57.856 D/GeckoViewAutoFill[C](22200): handleEvent: pagehide
[task 2022-06-03T10:58:29.281Z] 10:58:29     INFO -  06-03 10:57:57.856 E/GeckoLibLoad(24778): Load sqlite done
[task 2022-06-03T10:58:29.281Z] 10:58:29     INFO -  06-03 10:57:57.856 I/GeckoLoader(24778): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-06-03T10:58:29.281Z] 10:58:29     INFO -  06-03 10:57:57.856 E/GeckoLibLoad(24778): Load nss start
[task 2022-06-03T10:58:29.281Z] 10:58:29     INFO -  06-03 10:57:57.856 E/GeckoLibLoad(24778): Load nss done
[task 2022-06-03T10:58:29.281Z] 10:58:29     INFO -  06-03 10:57:57.856 I/GeckoLoader(24778): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-06-03T10:58:29.281Z] 10:58:29     INFO -  06-03 10:57:57.856 D/GeckoViewXUL( 3429): DidChangeBrowserRemoteness
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.856 D/GeckoViewNavigation( 3429): sessionContextId=null
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.858 D/GeckoViewAutoFill( 3429): receiveMessage Clear
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.866 E/GeckoLibLoad(24778): Loaded libs in 10.062443ms total, 10ms(10ms) user, 0ms(0ms) system, 0(0) faults
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.866 D/GeckoThread(24778): State changed to LIBS_READY
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.866 W/GeckoThread(24778): zerdatime 435988 - runGecko
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.884 E/eglCodecCommon(24641): glUtilsParamSize: unknow param 0x00008caa
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.930 D/GeckoThread(24778): State changed to RUNNING
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.953 D/GeckoViewStartup(24778): observe: content-process-ready-for-script
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.955 D/GeckoViewConsole(24778): enabled = true
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.975 E/eglCodecCommon(24641): glUtilsParamSize: unknow param 0x00008caa
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.984 D/GeckoViewXUL( 3429): receiveMessage GeckoView:ContentModuleLoaded {}
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.995 E/eglCodecCommon(24641): glUtilsParamSize: unknow param 0x00008caa
[task 2022-06-03T10:58:29.282Z] 10:58:29     INFO -  06-03 10:57:57.995 D/GeckoViewSelectionActionDelegate[C](24778): handleEvent: visibilitychange
[task 2022-06-03T10:58:29.283Z] 10:58:29     INFO -  06-03 10:57:57.998 D/GeckoViewAutoFill[C](24778): handleEvent: pagehide
[task 2022-06-03T10:58:29.283Z] 10:58:29     INFO -  06-03 10:57:58.000 D/GeckoViewAutoFill( 3429): receiveMessage Clear
[task 2022-06-03T10:58:29.283Z] 10:58:29     INFO -  06-03 10:57:58.004 D/GeckoViewNavigation( 3429): onLocationChange
[task 2022-06-03T10:58:29.284Z] 10:58:29     INFO -  06-03 10:57:58.006 D/GeckoSession( 3429): handleMessage GeckoView:LocationChange uri=http://localhost:4245/assets/www/inputs.html
[task 2022-06-03T10:58:29.284Z] 10:58:29     INFO -  06-03 10:57:58.006 W/Isolated Web Content(24778): [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://localhost:4245/assets/www/inputs.html" line: 0}]
[task 2022-06-03T10:58:29.284Z] 10:58:29     INFO -  06-03 10:57:58.006 D/GeckoViewProgress( 3429): SecurityTracker onLocationChange: location=http://localhost:4245/assets/www/inputs.html, flags=0
[task 2022-06-03T10:58:29.284Z] 10:58:29     INFO -  06-03 10:57:58.007 D/GeckoViewProgress( 3429): ProgressTracker onLocationChange: location=http://localhost:4245/assets/www/inputs.html, flags=0
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.007 D/GeckoViewProgress( 3429): ProgressTracker changeLocation http://localhost:4245/assets/www/inputs.html
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.007 D/GeckoViewProgress( 3429): onSecurityChange
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.007 D/GeckoSession( 3429): handleMessage GeckoView:SecurityChanged uri=null
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.072 D/GeckoViewContent( 3429): handleEvent: pagetitlechanged
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.084 D/GeckoViewContentDelegateChild[C](24778): handleEvent: DOMContentLoaded
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.087 D/GeckoViewProgressDelegate[C](24778): handleEvent: DOMContentLoaded
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.088 D/GeckoViewProgress( 3429): receiveMessage: DOMContentLoaded
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.089 D/GeckoViewProgress( 3429): ProgressTracker handleEvent: DOMContentLoaded
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.089 D/GeckoViewProgress( 3429): ProgressTracker updateProgress
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.089 D/GeckoViewProgress( 3429): ProgressTracker updateProgress data={"prev":15,"uri":"http://localhost:4245/assets/www/inputs.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":true} progress=55
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.089 D/GeckoSession( 3429): handleMessage GeckoView:ProgressChanged uri=null
[task 2022-06-03T10:58:29.285Z] 10:58:29     INFO -  06-03 10:57:58.089 D/GeckoViewContentDelegateChild[C](24778): handleEvent: MozFirstContentfulPaint
[task 2022-06-03T10:58:29.286Z] 10:58:29     INFO -  06-03 10:57:58.090 D/GeckoViewContentDelegateParent( 3429): receiveMessage: DispatcherMessage
[task 2022-06-03T10:58:29.286Z] 10:58:29     INFO -  06-03 10:57:58.092 D/GeckoViewSelectionActionDelegate[C](24778): handleEvent: visibilitychange
[task 2022-06-03T10:58:29.286Z] 10:58:29     INFO -  06-03 10:57:58.092 D/GeckoViewAutoFill[C](24778): handleEvent: pagehide
[task 2022-06-03T10:58:29.286Z] 10:58:29     INFO -  06-03 10:57:58.096 E/eglCodecCommon(24641): glUtilsParamSize: unknow param 0x00008caa
[task 2022-06-03T10:58:29.286Z] 10:58:29     INFO -  06-03 10:58:00.856 D/ServiceAllocator( 3429): org.mozilla.gecko.process.GeckoChildProcessServices$tab36 updateBindings: IDLE priority, 6 importance, 0 successful binds, 0 failed binds, 2 successful unbinds
[task 2022-06-03T10:58:29.286Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): Error
[task 2022-06-03T10:58:29.286Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-06-03T10:58:29.286Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-06-03T10:58:29.287Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-06-03T10:58:29.287Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-06-03T10:58:29.287Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-06-03T10:58:29.287Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1775)
[task 2022-06-03T10:58:29.287Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1531)
[task 2022-06-03T10:58:29.288Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1506)
[task 2022-06-03T10:58:29.288Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:186)
[task 2022-06-03T10:58:29.288Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.testThat(SelectionActionDelegateTest.kt:271)
[task 2022-06-03T10:58:29.288Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.selectAll(SelectionActionDelegateTest.kt:185)
[task 2022-06-03T10:58:29.289Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2022-06-03T10:58:29.289Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2022-06-03T10:58:29.289Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2022-06-03T10:58:29.289Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2022-06-03T10:58:29.289Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2022-06-03T10:58:29.289Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[task 2022-06-03T10:58:29.290Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$org-mozilla-geckoview-test-rule-GeckoSessionTestRule$2(GeckoSessionTestRule.java:1460)
[task 2022-06-03T10:58:29.290Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2$$ExternalSyntheticLambda0.run(Unknown Source)
[task 2022-06-03T10:58:29.290Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
[task 2022-06-03T10:58:29.290Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
[task 2022-06-03T10:58:29.290Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2022-06-03T10:58:29.290Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-06-03T10:58:29.290Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-06-03T10:58:29.290Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at android.os.Looper.loop(Looper.java:154)
[task 2022-06-03T10:58:29.291Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2022-06-03T10:58:29.291Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2022-06-03T10:58:29.291Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2022-06-03T10:58:29.291Z] 10:58:29     INFO -  06-03 10:58:28.144 E/GeckoSessionTestRule( 3429): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2022-06-03T10:58:29.291Z] 10:58:29     INFO -  06-03 10:58:28.146 D/EGL_emulation(24641): eglMakeCurrent: 0x7860e8c7bb80: ver 3 0 (tinfo 0x7860e8cb4b20)
[task 2022-06-03T10:58:29.291Z] 10:58:29     INFO -  06-03 10:58:28.148 D/GeckoViewContent( 3429): handleEvent: DOMWindowClose
[task 2022-06-03T10:58:29.291Z] 10:58:29     INFO -  06-03 10:58:28.150 D/GeckoViewConsole( 3429): onEvent GeckoView:WebExtension:List null
[task 2022-06-03T10:58:29.291Z] 10:58:29     INFO -  06-03 10:58:28.153 E/GeckoSessionTestRule( 3429): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 selectAll[#text](org.mozilla.geckoview.test.SelectionActionDelegateTest)
[task 2022-06-03T10:58:29.292Z] 10:58:29  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.SelectionActionDelegateTest#selectAll[#text] | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-06-03T10:58:29.292Z] 10:58:29     INFO -  TEST-INFO took 32876ms
[task 2022-06-03T10:58:29.392Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=925
[task 2022-06-03T10:58:29.392Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2022-06-03T10:58:29.392Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2022-06-03T10:58:29.392Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=request_noClipboard[#text]
[task 2022-06-03T10:58:29.392Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SelectionActionDelegateTest
[task 2022-06-03T10:58:29.392Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=557
[task 2022-06-03T10:58:29.392Z] 10:58:29     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=385535759&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.