Closed
Bug 1761244
Opened 3 years ago
Closed 2 years ago
Intermittent org.mozilla.geckoview.test.PromptDelegateTest#dismissAuthTest | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
Categories
(GeckoView :: General, defect, P5)
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=372178403&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UJ8OWnFYQnC9yoaG8PxrOw/runs/0/artifacts/public/logs/live_backing.log
[task 2022-03-24T11:46:29.768Z] 11:46:29 INFO - TEST-START | org.mozilla.geckoview.test.PromptDelegateTest#dismissAuthTest
[task 2022-03-24T11:47:00.037Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=883
[task 2022-03-24T11:47:00.037Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2022-03-24T11:47:00.037Z] 11:47:00 INFO - org.mozilla.geckoview.test | Error in dismissAuthTest(org.mozilla.geckoview.test.PromptDelegateTest):
[task 2022-03-24T11:47:00.038Z] 11:47:00 INFO - org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-03-24T11:47:00.038Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-03-24T11:47:00.038Z] 11:47:00 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-03-24T11:47:00.038Z] 11:47:00 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-03-24T11:47:00.038Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-03-24T11:47:00.039Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1741)
[task 2022-03-24T11:47:00.039Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1522)
[task 2022-03-24T11:47:00.039Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1497)
[task 2022-03-24T11:47:00.039Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:181)
[task 2022-03-24T11:47:00.040Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.PromptDelegateTest.dismissAuthTest(PromptDelegateTest.kt:202)
[task 2022-03-24T11:47:00.040Z] 11:47:00 INFO - org.mozilla.geckoview.test |
[task 2022-03-24T11:47:00.040Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2022-03-24T11:47:00.040Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=dismissAuthTest
[task 2022-03-24T11:47:00.040Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.PromptDelegateTest
[task 2022-03-24T11:47:00.040Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-03-24T11:47:00.041Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-03-24T11:47:00.041Z] 11:47:00 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-03-24T11:47:00.041Z] 11:47:00 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-03-24T11:47:00.041Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-03-24T11:47:00.042Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1741)
[task 2022-03-24T11:47:00.042Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1522)
[task 2022-03-24T11:47:00.042Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1497)
[task 2022-03-24T11:47:00.042Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:181)
[task 2022-03-24T11:47:00.042Z] 11:47:00 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.PromptDelegateTest.dismissAuthTest(PromptDelegateTest.kt:202)
[task 2022-03-24T11:47:00.043Z] 11:47:00 INFO - org.mozilla.geckoview.test |
[task 2022-03-24T11:47:00.043Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=484
[task 2022-03-24T11:47:00.043Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2022-03-24T11:47:00.043Z] 11:47:00 INFO - Printing logcat for test:
[task 2022-03-24T11:47:00.130Z] 11:47:00 INFO - 03-24 11:46:29.234 E/GeckoSessionTestRule( 3395): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec dismissAuthTest(org.mozilla.geckoview.test.PromptDelegateTest)
[task 2022-03-24T11:47:00.131Z] 11:47:00 INFO - 03-24 11:46:29.234 E/GeckoSessionTestRule( 3395): before prepareStatement dismissAuthTest(org.mozilla.geckoview.test.PromptDelegateTest)
[task 2022-03-24T11:47:00.131Z] 11:47:00 INFO - 03-24 11:46:29.236 E/eglCodecCommon(14929): glUtilsParamSize: unknow param 0x00008caa
[task 2022-03-24T11:47:00.131Z] 11:47:00 INFO - 03-24 11:46:29.236 D/GeckoViewSelectionActionDelegate[C](22300): handleEvent: visibilitychange
[task 2022-03-24T11:47:00.131Z] 11:47:00 INFO - 03-24 11:46:29.236 D/GeckoViewAutoFill[C](22300): handleEvent: pagehide
[task 2022-03-24T11:47:00.131Z] 11:47:00 INFO - 03-24 11:46:29.236 D/GeckoViewAutofill(22300): Clearing auto-fill
[task 2022-03-24T11:47:00.131Z] 11:47:00 INFO - 03-24 11:46:29.238 D/GeckoViewStartup( 3395): onEvent GeckoView:StorageDelegate:Attached
[task 2022-03-24T11:47:00.132Z] 11:47:00 INFO - 03-24 11:46:29.244 I/ServiceChildProcess(22300): Destroying GeckoServiceChildProcess
[task 2022-03-24T11:47:00.132Z] 11:47:00 INFO - 03-24 11:46:29.245 I/art (22300): System.exit called, status: 0
[task 2022-03-24T11:47:00.132Z] 11:47:00 INFO - 03-24 11:46:29.245 I/AndroidRuntime(22300): VM exiting with result code 0, cleanup skipped.
[task 2022-03-24T11:47:00.132Z] 11:47:00 INFO - 03-24 11:46:29.250 D/GeckoViewNavigation( 3395): sessionContextId=null
[task 2022-03-24T11:47:00.132Z] 11:47:00 INFO - 03-24 11:46:29.254 E/eglCodecCommon(14929): glUtilsParamSize: unknow param 0x00008caa
[task 2022-03-24T11:47:00.133Z] 11:47:00 INFO - 03-24 11:46:29.261 E/eglCodecCommon(14929): glUtilsParamSize: unknow param 0x00008741
[task 2022-03-24T11:47:00.133Z] 11:47:00 INFO - 03-24 11:46:29.263 D/GeckoViewModule( 3395): registerListener ["GeckoViewContent:ExitFullScreen","GeckoView:ClearMatches","GeckoView:DisplayMatches","GeckoView:FindInPage","GeckoView:RestoreState","GeckoView:ScrollBy","GeckoView:ScrollTo","GeckoView:SetActive","GeckoView:SetFocused","GeckoView:UpdateInitData","GeckoView:ZoomToInput"]
[task 2022-03-24T11:47:00.133Z] 11:47:00 INFO - 03-24 11:46:29.263 D/GeckoViewNavigation( 3395): onInit
[task 2022-03-24T11:47:00.134Z] 11:47:00 INFO - 03-24 11:46:29.263 D/GeckoViewModule( 3395): registerListener ["GeckoView:GoBack","GeckoView:GoForward","GeckoView:GotoHistoryIndex","GeckoView:LoadUri","GeckoView:Reload","GeckoView:Stop","GeckoView:PurgeHistory"]
[task 2022-03-24T11:47:00.134Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewNavigation( 3395): onEnable
[task 2022-03-24T11:47:00.134Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewProcessHangMonitor( 3395): onInit
[task 2022-03-24T11:47:00.134Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewProcessHangMonitor( 3395): onEnable
[task 2022-03-24T11:47:00.134Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewModule( 3395): registerListener ["GeckoView:HangReportStop","GeckoView:HangReportWait"]
[task 2022-03-24T11:47:00.134Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewProgress( 3395): onEnable
[task 2022-03-24T11:47:00.135Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewSelectionActionDelegate[C](16146): handleEvent: visibilitychange
[task 2022-03-24T11:47:00.135Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoSession( 3395): handleMessage GeckoView:PageStart uri=about:blank
[task 2022-03-24T11:47:00.135Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewModule( 3395): registerListener GeckoView:FlushSessionState
[task 2022-03-24T11:47:00.135Z] 11:47:00 INFO - 03-24 11:46:29.264 E/GeckoSessionTestRule( 3395): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStart(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2022-03-24T11:47:00.136Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoSession( 3395): handleMessage GeckoView:LocationChange uri=about:blank
[task 2022-03-24T11:47:00.136Z] 11:47:00 INFO - 03-24 11:46:29.264 E/GeckoSessionTestRule( 3395): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String,java.util.List)
[task 2022-03-24T11:47:00.136Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewSettings( 3395): onInit
[task 2022-03-24T11:47:00.136Z] 11:47:00 INFO - 03-24 11:46:29.264 E/GeckoSessionTestRule( 3395): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2022-03-24T11:47:00.137Z] 11:47:00 INFO - 03-24 11:46:29.264 D/GeckoViewModule( 3395): registerListener ["GeckoView:GetUserAgent"]
[task 2022-03-24T11:47:00.137Z] 11:47:00 INFO - 03-24 11:46:29.264 E/GeckoSessionTestRule( 3395): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoBack(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-03-24T11:47:00.138Z] 11:47:00 INFO - 03-24 11:46:29.265 D/GeckoViewSettings( 3395): 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-03-24T11:47:00.138Z] 11:47:00 INFO - 03-24 11:46:29.265 E/GeckoSessionTestRule( 3395): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoForward(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-03-24T11:47:00.138Z] 11:47:00 INFO - 03-24 11:46:29.265 D/GeckoSession( 3395): handleMessage GeckoView:PageStop uri=null
[task 2022-03-24T11:47:00.138Z] 11:47:00 INFO - 03-24 11:46:29.265 E/GeckoSessionTestRule( 3395): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStop(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-03-24T11:47:00.139Z] 11:47:00 INFO - 03-24 11:46:29.265 D/GeckoViewModule( 3395): registerListener ["GeckoView:WebExtension:SetTabActive"]
[task 2022-03-24T11:47:00.139Z] 11:47:00 INFO - 03-24 11:46:29.265 E/GeckoSessionTestRule( 3395): after prepareStatement
[task 2022-03-24T11:47:00.139Z] 11:47:00 INFO - 03-24 11:46:29.265 D/GeckoViewModule( 3395): registerListener ["ContentBlocking:RequestLog"]
[task 2022-03-24T11:47:00.139Z] 11:47:00 INFO - 03-24 11:46:29.265 D/GeckoViewMediaControl( 3395): onEnable
[task 2022-03-24T11:47:00.140Z] 11:47:00 INFO - 03-24 11:46:29.265 D/GeckoViewModule( 3395): 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-03-24T11:47:00.140Z] 11:47:00 INFO - 03-24 11:46:29.265 D/GeckoViewSettings[C](16146): receiveMessage: SettingsUpdate
[task 2022-03-24T11:47:00.140Z] 11:47:00 INFO - 03-24 11:46:29.266 I/GeckoSession( 3395): zerdatime 319501 - chrome startup finished
[task 2022-03-24T11:47:00.140Z] 11:47:00 INFO - 03-24 11:46:29.268 D/GeckoViewXUL( 3395): receiveMessage GeckoView:ContentModuleLoaded {}
[task 2022-03-24T11:47:00.141Z] 11:47:00 INFO - 03-24 11:46:29.268 D/GeckoViewModule( 3395): dispatch GeckoView:LoadUri, data={"uri":"http://localhost:4245/basic-auth/foo/bar","flags":0,"headerFilter":1}
[task 2022-03-24T11:47:00.141Z] 11:47:00 INFO - 03-24 11:46:29.268 D/GeckoViewNavigation( 3395): onEvent: event=GeckoView:LoadUri, data={"uri":"http://localhost:4245/basic-auth/foo/bar","flags":0,"headerFilter":1}
[task 2022-03-24T11:47:00.141Z] 11:47:00 INFO - 03-24 11:46:29.269 W/GeckoEditableChild(16146): No editable parent
[task 2022-03-24T11:47:00.141Z] 11:47:00 INFO - 03-24 11:46:29.272 D/GeckoViewProgress( 3395): ProgressTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK
[task 2022-03-24T11:47:00.142Z] 11:47:00 INFO - 03-24 11:46:29.272 D/GeckoViewProgress( 3395): ProgressTracker onStateChange: uri=http://localhost:4245/basic-auth/foo/bar
[task 2022-03-24T11:47:00.142Z] 11:47:00 INFO - 03-24 11:46:29.272 D/GeckoViewProgress( 3395): ProgressTracker start http://localhost:4245/basic-auth/foo/bar
[task 2022-03-24T11:47:00.142Z] 11:47:00 INFO - 03-24 11:46:29.272 D/GeckoViewProgress( 3395): ProgressTracker updateProgress
[task 2022-03-24T11:47:00.142Z] 11:47:00 INFO - 03-24 11:46:29.272 D/GeckoViewProgress( 3395): ProgressTracker updateProgress data={"prev":0,"uri":"http://localhost:4245/basic-auth/foo/bar","locationChange":false,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":false} progress=15
[task 2022-03-24T11:47:00.142Z] 11:47:00 INFO - 03-24 11:46:29.273 D/GeckoViewProgress( 3395): StateTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK loadType=1
[task 2022-03-24T11:47:00.143Z] 11:47:00 INFO - 03-24 11:46:29.273 D/GeckoSession( 3395): handleMessage GeckoView:ProgressChanged uri=null
[task 2022-03-24T11:47:00.143Z] 11:47:00 INFO - 03-24 11:46:29.273 D/GeckoSession( 3395): handleMessage GeckoView:PageStart uri=http://localhost:4245/basic-auth/foo/bar
[task 2022-03-24T11:47:00.143Z] 11:47:00 INFO - 03-24 11:46:29.274 D/GeckoViewAutocomplete( 3395): fetchLogins for localhost
[task 2022-03-24T11:47:00.143Z] 11:47:00 INFO - 03-24 11:46:29.284 I/art (22347): Late-enabling -Xcheck:jni
[task 2022-03-24T11:47:00.143Z] 11:47:00 INFO - 03-24 11:46:29.285 W/art (22347): Unexpected CPU variant for X86 using defaults: x86_64
[task 2022-03-24T11:47:00.143Z] 11:47:00 INFO - 03-24 11:46:29.289 I/ActivityManager( 1650): Start proc 22347:org.mozilla.geckoview.test:tab19/u0a62 for service org.mozilla.geckoview.test/org.mozilla.gecko.process.GeckoChildProcessServices$tab19
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.291 D/ServiceAllocator( 3395): org.mozilla.gecko.process.GeckoChildProcessServices$tab19 updateBindings: FOREGROUND priority, 0 importance, 3 successful binds, 0 failed binds, 0 successful unbinds
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.302 I/MultiDex(22347): VM with version 2.1.0 has multidex support
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.302 I/MultiDex(22347): Installing application
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.302 I/MultiDex(22347): VM has multidex support, MultiDex support library is disabled.
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.303 I/ServiceChildProcess(22347): onCreate
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.304 D/GeckoThread(22347): State changed to LAUNCHED
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.304 I/GeckoThread(22347): preparing to run Gecko
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.305 I/ActivityManager( 1650): Process org.mozilla.geckoview.test:tab6 (pid 22300) has died
[task 2022-03-24T11:47:00.144Z] 11:47:00 INFO - 03-24 11:46:29.305 D/ActivityManager( 1650): cleanUpApplicationRecord -- 22300
[task 2022-03-24T11:47:00.145Z] 11:47:00 INFO - 03-24 11:46:29.306 D/GeckoViewContent( 3395): observe: ipc:content-shutdown
[task 2022-03-24T11:47:00.145Z] 11:47:00 INFO - 03-24 11:46:29.307 I/Gecko ( 3395): [Parent 3395, Unnamed thread 73ac38a21ce0] WARNING: waitpid failed pid:22300 errno:10: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_posix.cc:221
[task 2022-03-24T11:47:00.145Z] 11:47:00 INFO - 03-24 11:46:29.307 D/ServiceAllocator( 3395): org.mozilla.gecko.process.GeckoChildProcessServices$tab19 updateBindings: FOREGROUND priority, 2 importance, 0 successful binds, 0 failed binds, 0 successful unbinds
[task 2022-03-24T11:47:00.145Z] 11:47:00 INFO - 03-24 11:46:29.308 D/GeckoViewXUL( 3395): WillChangeBrowserRemoteness
[task 2022-03-24T11:47:00.145Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: MOZ_CRASHREPORTER=1
[task 2022-03-24T11:47:00.145Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: MOZ_CRASHREPORTER_SHUTDOWN=1
[task 2022-03-24T11:47:00.145Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: XPCOM_DEBUG_BREAK=stack
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: MOZ_DISABLE_NONLOCAL_CONNECTIONS=1
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: MOZ_IN_AUTOMATION=1
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: R_LOG_VERBOSE=1
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: R_LOG_LEVEL=6
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: R_LOG_DESTINATION=stderr
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: MOZ_WEBRENDER=1
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoThread(22347): env var: MOZ_FORCE_ENABLE_FISSION=1
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.309 D/GeckoViewXUL( 3395): DidChangeBrowserRemoteness
[task 2022-03-24T11:47:00.146Z] 11:47:00 INFO - 03-24 11:46:29.310 D/GeckoViewNavigation( 3395): sessionContextId=null
[task 2022-03-24T11:47:00.147Z] 11:47:00 INFO - 03-24 11:46:29.311 D/GeckoViewSelectionActionDelegate[C](16146): handleEvent: visibilitychange
[task 2022-03-24T11:47:00.147Z] 11:47:00 INFO - 03-24 11:46:29.312 D/GeckoThread(22347): State changed to MOZGLUE_READY
[task 2022-03-24T11:47:00.147Z] 11:47:00 INFO - 03-24 11:46:29.312 D/GeckoViewAutoFill[C](16146): handleEvent: pagehide
[task 2022-03-24T11:47:00.147Z] 11:47:00 INFO - 03-24 11:46:29.312 D/GeckoViewAutofill(16146): Clearing auto-fill
[task 2022-03-24T11:47:00.147Z] 11:47:00 INFO - 03-24 11:46:29.312 I/GeckoLoader(22347): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-03-24T11:47:00.147Z] 11:47:00 INFO - 03-24 11:46:29.312 I/GeckoLoader(22347): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-03-24T11:47:00.148Z] 11:47:00 INFO - 03-24 11:46:29.312 E/GeckoLibLoad(22347): Load sqlite start
[task 2022-03-24T11:47:00.148Z] 11:47:00 INFO - 03-24 11:46:29.313 E/GeckoLibLoad(22347): Load sqlite done
[task 2022-03-24T11:47:00.148Z] 11:47:00 INFO - 03-24 11:46:29.313 I/GeckoLoader(22347): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-03-24T11:47:00.148Z] 11:47:00 INFO - 03-24 11:46:29.313 E/GeckoLibLoad(22347): Load nss start
[task 2022-03-24T11:47:00.148Z] 11:47:00 INFO - 03-24 11:46:29.313 E/GeckoLibLoad(22347): Load nss done
[task 2022-03-24T11:47:00.148Z] 11:47:00 INFO - 03-24 11:46:29.313 I/GeckoLoader(22347): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-03-24T11:47:00.149Z] 11:47:00 INFO - 03-24 11:46:29.327 E/GeckoLibLoad(22347): Loaded libs in 13.765543ms total, 10ms(10ms) user, 0ms(0ms) system, 0(0) faults
[task 2022-03-24T11:47:00.149Z] 11:47:00 INFO - 03-24 11:46:29.327 D/GeckoThread(22347): State changed to LIBS_READY
[task 2022-03-24T11:47:00.149Z] 11:47:00 INFO - 03-24 11:46:29.327 W/GeckoThread(22347): zerdatime 319562 - runGecko
[task 2022-03-24T11:47:00.149Z] 11:47:00 INFO - 03-24 11:46:29.386 D/GeckoThread(22347): State changed to RUNNING
[task 2022-03-24T11:47:00.149Z] 11:47:00 INFO - 03-24 11:46:29.408 D/GeckoViewStartup(22347): observe: content-process-ready-for-script
[task 2022-03-24T11:47:00.149Z] 11:47:00 INFO - 03-24 11:46:29.410 D/GeckoViewConsole(22347): enabled = true
[task 2022-03-24T11:47:00.149Z] 11:47:00 INFO - 03-24 11:46:29.436 D/GeckoViewXUL( 3395): receiveMessage GeckoView:ContentModuleLoaded {}
[task 2022-03-24T11:47:00.149Z] 11:47:00 INFO - 03-24 11:46:29.445 D/GeckoViewSelectionActionDelegate[C](22347): handleEvent: visibilitychange
[task 2022-03-24T11:47:00.150Z] 11:47:00 INFO - 03-24 11:46:29.446 D/GeckoViewAutoFill[C](22347): handleEvent: pagehide
[task 2022-03-24T11:47:00.150Z] 11:47:00 INFO - 03-24 11:46:29.448 D/GeckoViewAutofill(22347): Clearing auto-fill
[task 2022-03-24T11:47:00.150Z] 11:47:00 INFO - 03-24 11:46:29.452 W/Isolated Web Content(22347): [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use “<!DOCTYPE html>”." {file: "http://localhost:4245/basic-auth/foo/bar" line: 0}]
[task 2022-03-24T11:47:00.150Z] 11:47:00 INFO - 03-24 11:46:29.452 D/GeckoViewNavigation( 3395): onLocationChange
[task 2022-03-24T11:47:00.150Z] 11:47:00 INFO - 03-24 11:46:29.454 D/GeckoSession( 3395): handleMessage GeckoView:LocationChange uri=http://localhost:4245/basic-auth/foo/bar
[task 2022-03-24T11:47:00.151Z] 11:47:00 INFO - 03-24 11:46:29.454 D/GeckoViewProgress( 3395): SecurityTracker onLocationChange: location=http://localhost:4245/basic-auth/foo/bar, flags=0
[task 2022-03-24T11:47:00.151Z] 11:47:00 INFO - 03-24 11:46:29.455 D/GeckoViewProgress( 3395): ProgressTracker onLocationChange: location=http://localhost:4245/basic-auth/foo/bar, flags=0
[task 2022-03-24T11:47:00.151Z] 11:47:00 INFO - 03-24 11:46:29.455 D/GeckoViewProgress( 3395): ProgressTracker changeLocation http://localhost:4245/basic-auth/foo/bar
[task 2022-03-24T11:47:00.151Z] 11:47:00 INFO - 03-24 11:46:29.455 D/GeckoViewProgress( 3395): onSecurityChange
[task 2022-03-24T11:47:00.151Z] 11:47:00 INFO - 03-24 11:46:29.455 D/GeckoSession( 3395): handleMessage GeckoView:SecurityChanged uri=null
[task 2022-03-24T11:47:00.151Z] 11:47:00 INFO - 03-24 11:46:29.489 D/GeckoViewContent( 3395): handleEvent: pagetitlechanged
[task 2022-03-24T11:47:00.151Z] 11:47:00 INFO - 03-24 11:46:29.491 D/GeckoViewContentDelegateChild[C](22347): handleEvent: DOMContentLoaded
[task 2022-03-24T11:47:00.152Z] 11:47:00 INFO - 03-24 11:46:29.492 D/GeckoViewProgressDelegate[C](22347): handleEvent: DOMContentLoaded
[task 2022-03-24T11:47:00.152Z] 11:47:00 INFO - 03-24 11:46:29.492 D/GeckoViewProgress( 3395): receiveMessage: DOMContentLoaded
[task 2022-03-24T11:47:00.152Z] 11:47:00 INFO - 03-24 11:46:29.492 D/GeckoViewProgress( 3395): ProgressTracker handleEvent: DOMContentLoaded
[task 2022-03-24T11:47:00.152Z] 11:47:00 INFO - 03-24 11:46:29.492 D/GeckoViewProgress( 3395): ProgressTracker updateProgress
[task 2022-03-24T11:47:00.152Z] 11:47:00 INFO - 03-24 11:46:29.493 D/GeckoViewProgress( 3395): ProgressTracker updateProgress data={"prev":15,"uri":"http://localhost:4245/basic-auth/foo/bar","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":true} progress=55
[task 2022-03-24T11:47:00.153Z] 11:47:00 INFO - 03-24 11:46:29.493 D/GeckoSession( 3395): handleMessage GeckoView:ProgressChanged uri=null
[task 2022-03-24T11:47:00.153Z] 11:47:00 INFO - 03-24 11:46:30.740 D/GeckoIdleService( 3395): Get idle time: time since reset 5009 msec
[task 2022-03-24T11:47:00.153Z] 11:47:00 INFO - 03-24 11:46:30.740 D/GeckoIdleService( 3395): Idle timer callback: current idle time 5009 msec
[task 2022-03-24T11:47:00.153Z] 11:47:00 INFO - 03-24 11:46:30.740 D/GeckoIdleService( 3395): next timeout 4294967289991 msec from now
[task 2022-03-24T11:47:00.153Z] 11:47:00 INFO - 03-24 11:46:30.740 D/GeckoIdleService( 3395): SetTimerExpiryIfBefore: next timeout 4294967289991 msec from now
[task 2022-03-24T11:47:00.153Z] 11:47:00 INFO - 03-24 11:46:30.740 D/GeckoIdleService( 3395): reset timer expiry to 4294967290000 msec from now
[task 2022-03-24T11:47:00.153Z] 11:47:00 INFO - 03-24 11:46:30.740 D/GeckoIdleService( 3395): Idle timer callback: tell observer 0x73ac250df2c8 user is idle
[task 2022-03-24T11:47:00.153Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): Error
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1741)
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1522)
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1497)
[task 2022-03-24T11:47:00.154Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:181)
[task 2022-03-24T11:47:00.155Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.PromptDelegateTest.dismissAuthTest(PromptDelegateTest.kt:202)
[task 2022-03-24T11:47:00.155Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at java.lang.reflect.Method.invoke(Native Method)
[task 2022-03-24T11:47:00.155Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2022-03-24T11:47:00.155Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2022-03-24T11:47:00.155Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2022-03-24T11:47:00.155Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2022-03-24T11:47:00.155Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.junit.rules.Verifier$1.evaluate(Verifier.java:35)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$org-mozilla-geckoview-test-rule-GeckoSessionTestRule$2(GeckoSessionTestRule.java:1451)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2$$ExternalSyntheticLambda0.run(Unknown Source)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at java.util.concurrent.FutureTask.run(FutureTask.java:237)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at android.os.Looper.loop(Looper.java:154)
[task 2022-03-24T11:47:00.156Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at java.lang.reflect.Method.invoke(Native Method)
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - 03-24 11:46:59.494 E/GeckoSessionTestRule( 3395): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - 03-24 11:46:59.496 D/GeckoViewContent( 3395): handleEvent: DOMWindowClose
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - 03-24 11:46:59.497 D/GeckoViewConsole( 3395): onEvent GeckoView:WebExtension:List null
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - 03-24 11:46:59.500 E/GeckoSessionTestRule( 3395): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 dismissAuthTest(org.mozilla.geckoview.test.PromptDelegateTest)
[task 2022-03-24T11:47:00.157Z] 11:47:00 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.PromptDelegateTest#dismissAuthTest | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - TEST-INFO took 30363ms
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=883
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2022-03-24T11:47:00.157Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2022-03-24T11:47:00.158Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=failedShareReturnsDataError
[task 2022-03-24T11:47:00.158Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.PromptDelegateTest
[task 2022-03-24T11:47:00.158Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=485
[task 2022-03-24T11:47:00.158Z] 11:47:00 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2022-03-24T11:47:00.158Z] 11:47:00 INFO - TEST-START | org.mozilla.geckoview.test.PromptDelegateTest#failedShareReturnsDataError
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 3•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Reporter | ||
Comment 4•2 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=387839757&repo=autoland
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Comment hidden (Intermittent Failures Robot) |
Comment 6•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: REOPENED → RESOLVED
Closed: 3 years ago → 2 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•