Intermittent org.mozilla.geckoview.test.WebNotificationTest#clickNotificationParceled | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
Categories
(GeckoView :: General, defect, P5)
Tracking
(Not tracked)
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=374009694&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/RSVznkR7Qa2bli7PG24DiA/runs/1/artifacts/public/logs/live_backing.log
[task 2022-04-10T22:17:18.352Z] 22:17:18 INFO - TEST-START | org.mozilla.geckoview.test.WebNotificationTest#clickNotificationParceled
[task 2022-04-10T22:17:48.608Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=884
[task 2022-04-10T22:17:48.609Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2022-04-10T22:17:48.609Z] 22:17:48 INFO - org.mozilla.geckoview.test | Error in clickNotificationParceled(org.mozilla.geckoview.test.WebNotificationTest):
[task 2022-04-10T22:17:48.609Z] 22:17:48 INFO - org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-04-10T22:17:48.610Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-04-10T22:17:48.610Z] 22:17:48 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-04-10T22:17:48.610Z] 22:17:48 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-04-10T22:17:48.610Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-04-10T22:17:48.611Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1741)
[task 2022-04-10T22:17:48.611Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1522)
[task 2022-04-10T22:17:48.612Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1497)
[task 2022-04-10T22:17:48.612Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:181)
[task 2022-04-10T22:17:48.612Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.WebNotificationTest.setup(WebNotificationTest.kt:23)
[task 2022-04-10T22:17:48.613Z] 22:17:48 INFO - org.mozilla.geckoview.test |
[task 2022-04-10T22:17:48.613Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2022-04-10T22:17:48.613Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=clickNotificationParceled
[task 2022-04-10T22:17:48.614Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.WebNotificationTest
[task 2022-04-10T22:17:48.614Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-04-10T22:17:48.614Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-04-10T22:17:48.615Z] 22:17:48 INFO - org.mozilla.geckoview.test | at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-04-10T22:17:48.615Z] 22:17:48 INFO - org.mozilla.geckoview.test | at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-04-10T22:17:48.615Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-04-10T22:17:48.615Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1741)
[task 2022-04-10T22:17:48.616Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1522)
[task 2022-04-10T22:17:48.616Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1497)
[task 2022-04-10T22:17:48.616Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:181)
[task 2022-04-10T22:17:48.617Z] 22:17:48 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.WebNotificationTest.setup(WebNotificationTest.kt:23)
[task 2022-04-10T22:17:48.617Z] 22:17:48 INFO - org.mozilla.geckoview.test |
[task 2022-04-10T22:17:48.617Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=871
[task 2022-04-10T22:17:48.617Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2022-04-10T22:17:48.617Z] 22:17:48 INFO - Printing logcat for test:
[task 2022-04-10T22:17:48.695Z] 22:17:48 INFO - 04-10 22:17:18.327 E/GeckoSessionTestRule( 3483): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec clickNotificationParceled(org.mozilla.geckoview.test.WebNotificationTest)
[task 2022-04-10T22:17:48.695Z] 22:17:48 INFO - 04-10 22:17:18.327 E/GeckoSessionTestRule( 3483): before prepareStatement clickNotificationParceled(org.mozilla.geckoview.test.WebNotificationTest)
[task 2022-04-10T22:17:48.695Z] 22:17:48 INFO - 04-10 22:17:18.327 D/GeckoViewMediaControl( 3483): onDisable
[task 2022-04-10T22:17:48.695Z] 22:17:48 INFO - 04-10 22:17:18.327 D/GeckoViewModule( 3483): unregisterListener
[task 2022-04-10T22:17:48.696Z] 22:17:48 INFO - 04-10 22:17:18.330 D/GeckoViewSelectionActionDelegate[C]( 2205): handleEvent: visibilitychange
[task 2022-04-10T22:17:48.696Z] 22:17:48 INFO - 04-10 22:17:18.330 D/GeckoViewAutoFill[C]( 2205): handleEvent: pagehide
[task 2022-04-10T22:17:48.696Z] 22:17:48 INFO - 04-10 22:17:18.330 D/GeckoViewAutofill( 2205): Clearing auto-fill
[task 2022-04-10T22:17:48.696Z] 22:17:48 INFO - 04-10 22:17:18.330 E/eglCodecCommon(23226): glUtilsParamSize: unknow param 0x00008caa
[task 2022-04-10T22:17:48.696Z] 22:17:48 INFO - 04-10 22:17:18.332 D/GeckoViewStartup( 3483): onEvent GeckoView:StorageDelegate:Attached
[task 2022-04-10T22:17:48.697Z] 22:17:48 INFO - 04-10 22:17:18.338 I/ServiceChildProcess( 2205): Destroying GeckoServiceChildProcess
[task 2022-04-10T22:17:48.697Z] 22:17:48 INFO - 04-10 22:17:18.339 I/art ( 2205): System.exit called, status: 0
[task 2022-04-10T22:17:48.697Z] 22:17:48 INFO - 04-10 22:17:18.339 I/AndroidRuntime( 2205): VM exiting with result code 0, cleanup skipped.
[task 2022-04-10T22:17:48.698Z] 22:17:48 INFO - 04-10 22:17:18.343 D/GeckoViewNavigation( 3483): sessionContextId=null
[task 2022-04-10T22:17:48.698Z] 22:17:48 INFO - 04-10 22:17:18.347 E/eglCodecCommon(23226): glUtilsParamSize: unknow param 0x00008caa
[task 2022-04-10T22:17:48.698Z] 22:17:48 INFO - 04-10 22:17:18.355 E/eglCodecCommon(23226): glUtilsParamSize: unknow param 0x00008741
[task 2022-04-10T22:17:48.700Z] 22:17:48 INFO - 04-10 22:17:18.358 D/GeckoViewModule( 3483): 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-04-10T22:17:48.700Z] 22:17:48 INFO - 04-10 22:17:18.359 D/GeckoViewNavigation( 3483): onInit
[task 2022-04-10T22:17:48.700Z] 22:17:48 INFO - 04-10 22:17:18.359 D/GeckoViewModule( 3483): registerListener ["GeckoView:GoBack","GeckoView:GoForward","GeckoView:GotoHistoryIndex","GeckoView:LoadUri","GeckoView:Reload","GeckoView:Stop","GeckoView:PurgeHistory"]
[task 2022-04-10T22:17:48.700Z] 22:17:48 INFO - 04-10 22:17:18.359 D/GeckoViewNavigation( 3483): onEnable
[task 2022-04-10T22:17:48.700Z] 22:17:48 INFO - 04-10 22:17:18.359 D/GeckoViewProcessHangMonitor( 3483): onInit
[task 2022-04-10T22:17:48.700Z] 22:17:48 INFO - 04-10 22:17:18.360 D/GeckoViewProcessHangMonitor( 3483): onEnable
[task 2022-04-10T22:17:48.701Z] 22:17:48 INFO - 04-10 22:17:18.360 D/GeckoViewModule( 3483): registerListener ["GeckoView:HangReportStop","GeckoView:HangReportWait"]
[task 2022-04-10T22:17:48.701Z] 22:17:48 INFO - 04-10 22:17:18.360 D/GeckoViewProgress( 3483): onEnable
[task 2022-04-10T22:17:48.701Z] 22:17:48 INFO - 04-10 22:17:18.360 D/GeckoSession( 3483): handleMessage GeckoView:PageStart uri=about:blank
[task 2022-04-10T22:17:48.701Z] 22:17:48 INFO - 04-10 22:17:18.360 E/GeckoSessionTestRule( 3483): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStart(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2022-04-10T22:17:48.701Z] 22:17:48 INFO - 04-10 22:17:18.360 D/GeckoSession( 3483): handleMessage GeckoView:LocationChange uri=about:blank
[task 2022-04-10T22:17:48.701Z] 22:17:48 INFO - 04-10 22:17:18.360 E/GeckoSessionTestRule( 3483): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String,java.util.List)
[task 2022-04-10T22:17:48.701Z] 22:17:48 INFO - 04-10 22:17:18.360 E/GeckoSessionTestRule( 3483): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2022-04-10T22:17:48.701Z] 22:17:48 INFO - 04-10 22:17:18.360 E/GeckoSessionTestRule( 3483): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoBack(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-04-10T22:17:48.702Z] 22:17:48 INFO - 04-10 22:17:18.360 E/GeckoSessionTestRule( 3483): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoForward(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-04-10T22:17:48.702Z] 22:17:48 INFO - 04-10 22:17:18.360 D/GeckoSession( 3483): handleMessage GeckoView:PageStop uri=null
[task 2022-04-10T22:17:48.702Z] 22:17:48 INFO - 04-10 22:17:18.360 E/GeckoSessionTestRule( 3483): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStop(org.mozilla.geckoview.GeckoSession,boolean)
[task 2022-04-10T22:17:48.702Z] 22:17:48 INFO - 04-10 22:17:18.360 D/GeckoViewModule( 3483): registerListener GeckoView:FlushSessionState
[task 2022-04-10T22:17:48.702Z] 22:17:48 INFO - 04-10 22:17:18.360 E/GeckoSessionTestRule( 3483): after prepareStatement
[task 2022-04-10T22:17:48.702Z] 22:17:48 INFO - 04-10 22:17:18.360 D/GeckoViewSelectionActionDelegate[C]( 1329): handleEvent: visibilitychange
[task 2022-04-10T22:17:48.702Z] 22:17:48 INFO - 04-10 22:17:18.361 D/GeckoViewSettings( 3483): onInit
[task 2022-04-10T22:17:48.702Z] 22:17:48 INFO - 04-10 22:17:18.361 D/GeckoViewModule( 3483): registerListener ["GeckoView:GetUserAgent"]
[task 2022-04-10T22:17:48.703Z] 22:17:48 INFO - 04-10 22:17:18.361 D/GeckoViewSettings( 3483): 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-04-10T22:17:48.703Z] 22:17:48 INFO - 04-10 22:17:18.362 D/GeckoViewModule( 3483): registerListener ["GeckoView:WebExtension:SetTabActive"]
[task 2022-04-10T22:17:48.703Z] 22:17:48 INFO - 04-10 22:17:18.362 D/GeckoViewModule( 3483): registerListener ["ContentBlocking:RequestLog"]
[task 2022-04-10T22:17:48.703Z] 22:17:48 INFO - 04-10 22:17:18.362 D/GeckoViewSettings[C]( 1329): receiveMessage: SettingsUpdate
[task 2022-04-10T22:17:48.703Z] 22:17:48 INFO - 04-10 22:17:18.362 D/GeckoViewMediaControl( 3483): onEnable
[task 2022-04-10T22:17:48.704Z] 22:17:48 INFO - 04-10 22:17:18.363 D/GeckoViewModule( 3483): 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-04-10T22:17:48.704Z] 22:17:48 INFO - 04-10 22:17:18.365 I/GeckoSession( 3483): zerdatime 713024 - chrome startup finished
[task 2022-04-10T22:17:48.704Z] 22:17:48 INFO - 04-10 22:17:18.367 W/GeckoEditableChild( 1329): No editable parent
[task 2022-04-10T22:17:48.704Z] 22:17:48 INFO - 04-10 22:17:18.368 D/GeckoViewXUL( 3483): receiveMessage GeckoView:ContentModuleLoaded {}
[task 2022-04-10T22:17:48.704Z] 22:17:48 INFO - 04-10 22:17:18.368 D/GeckoViewModule( 3483): dispatch GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/hello.html","flags":0,"headerFilter":1}
[task 2022-04-10T22:17:48.704Z] 22:17:48 INFO - 04-10 22:17:18.368 D/GeckoViewNavigation( 3483): onEvent: event=GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/hello.html","flags":0,"headerFilter":1}
[task 2022-04-10T22:17:48.704Z] 22:17:48 INFO - 04-10 22:17:18.374 D/GeckoViewProgress( 3483): ProgressTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.374 D/GeckoViewProgress( 3483): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello.html
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.374 D/GeckoViewProgress( 3483): ProgressTracker start http://localhost:4245/assets/www/hello.html
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.374 D/GeckoViewProgress( 3483): ProgressTracker updateProgress
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.374 D/GeckoViewProgress( 3483): ProgressTracker updateProgress data={"prev":0,"uri":"http://localhost:4245/assets/www/hello.html","locationChange":false,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":false} progress=15
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.374 D/GeckoSession( 3483): handleMessage GeckoView:ProgressChanged uri=null
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.375 D/GeckoViewProgress( 3483): StateTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK loadType=1
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.375 D/GeckoSession( 3483): handleMessage GeckoView:PageStart uri=http://localhost:4245/assets/www/hello.html
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.384 I/art ( 2270): Late-enabling -Xcheck:jni
[task 2022-04-10T22:17:48.705Z] 22:17:48 INFO - 04-10 22:17:18.384 W/art ( 2270): Unexpected CPU variant for X86 using defaults: x86_64
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.389 I/ActivityManager( 1652): Start proc 2270:org.mozilla.geckoview.test:tab30/u0a62 for service org.mozilla.geckoview.test/org.mozilla.gecko.process.GeckoChildProcessServices$tab30
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.390 D/ServiceAllocator( 3483): org.mozilla.gecko.process.GeckoChildProcessServices$tab30 updateBindings: FOREGROUND priority, 0 importance, 3 successful binds, 0 failed binds, 0 successful unbinds
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.403 I/MultiDex( 2270): VM with version 2.1.0 has multidex support
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.403 I/MultiDex( 2270): Installing application
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.403 I/MultiDex( 2270): VM has multidex support, MultiDex support library is disabled.
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.404 I/ServiceChildProcess( 2270): onCreate
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.406 D/GeckoThread( 2270): State changed to LAUNCHED
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.406 I/GeckoThread( 2270): preparing to run Gecko
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.409 D/ServiceAllocator( 3483): org.mozilla.gecko.process.GeckoChildProcessServices$tab30 updateBindings: FOREGROUND priority, 2 importance, 0 successful binds, 0 failed binds, 0 successful unbinds
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: MOZ_CRASHREPORTER=1
[task 2022-04-10T22:17:48.706Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: MOZ_CRASHREPORTER_SHUTDOWN=1
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: XPCOM_DEBUG_BREAK=stack
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: MOZ_DISABLE_NONLOCAL_CONNECTIONS=1
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: MOZ_IN_AUTOMATION=1
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: R_LOG_VERBOSE=1
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: R_LOG_LEVEL=6
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: R_LOG_DESTINATION=stderr
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: MOZ_WEBRENDER=1
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.410 D/GeckoThread( 2270): env var: MOZ_FORCE_ENABLE_FISSION=1
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.411 D/GeckoViewXUL( 3483): WillChangeBrowserRemoteness
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.412 D/GeckoThread( 2270): State changed to MOZGLUE_READY
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.413 D/GeckoViewXUL( 3483): DidChangeBrowserRemoteness
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.413 D/GeckoViewNavigation( 3483): sessionContextId=null
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.413 I/GeckoLoader( 2270): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.413 I/GeckoLoader( 2270): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.413 E/GeckoLibLoad( 2270): Load sqlite start
[task 2022-04-10T22:17:48.707Z] 22:17:48 INFO - 04-10 22:17:18.413 D/GeckoViewSelectionActionDelegate[C]( 1329): handleEvent: visibilitychange
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.413 E/GeckoLibLoad( 2270): Load sqlite done
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.414 I/GeckoLoader( 2270): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.414 E/GeckoLibLoad( 2270): Load nss start
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.414 E/GeckoLibLoad( 2270): Load nss done
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.414 I/GeckoLoader( 2270): Library base=/data/app/org.mozilla.geckoview.test-1/lib/x86_64
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.414 D/GeckoViewAutoFill[C]( 1329): handleEvent: pagehide
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.414 D/GeckoViewAutofill( 1329): Clearing auto-fill
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.416 I/ActivityManager( 1652): Process org.mozilla.geckoview.test:tab2 (pid 2205) has died
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.416 D/ActivityManager( 1652): cleanUpApplicationRecord -- 2205
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.418 D/GeckoViewContent( 3483): observe: ipc:content-shutdown
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.419 I/Gecko ( 3483): [Parent 3483, Unnamed thread 7511d8d21460] WARNING: waitpid failed pid:2205 errno:10: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_posix.cc:221
[task 2022-04-10T22:17:48.708Z] 22:17:48 INFO - 04-10 22:17:18.421 E/GeckoLibLoad( 2270): Loaded libs in 7.159488ms total, 0ms(0ms) user, 0ms(0ms) system, 0(0) faults
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.421 D/GeckoThread( 2270): State changed to LIBS_READY
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.421 W/GeckoThread( 2270): zerdatime 713080 - runGecko
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.480 D/GeckoThread( 2270): State changed to RUNNING
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.498 D/GeckoViewStartup( 2270): observe: content-process-ready-for-script
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.500 D/GeckoViewConsole( 2270): enabled = true
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.519 D/GeckoViewXUL( 3483): receiveMessage GeckoView:ContentModuleLoaded {}
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.525 D/GeckoViewSelectionActionDelegate[C]( 2270): handleEvent: visibilitychange
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.526 D/GeckoViewAutoFill[C]( 2270): handleEvent: pagehide
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.528 D/GeckoViewAutofill( 2270): Clearing auto-fill
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.533 D/GeckoViewNavigation( 3483): onLocationChange
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.533 W/Isolated Web Content( 2270): [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/hello.html" line: 0}]
[task 2022-04-10T22:17:48.709Z] 22:17:48 INFO - 04-10 22:17:18.534 D/GeckoSession( 3483): handleMessage GeckoView:LocationChange uri=http://localhost:4245/assets/www/hello.html
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:18.534 D/GeckoViewProgress( 3483): SecurityTracker onLocationChange: location=http://localhost:4245/assets/www/hello.html, flags=0
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:18.535 D/GeckoViewProgress( 3483): ProgressTracker onLocationChange: location=http://localhost:4245/assets/www/hello.html, flags=0
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:18.535 D/GeckoViewProgress( 3483): ProgressTracker changeLocation http://localhost:4245/assets/www/hello.html
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:18.535 D/GeckoViewProgress( 3483): onSecurityChange
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:18.536 D/GeckoSession( 3483): handleMessage GeckoView:SecurityChanged uri=null
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:18.574 D/GeckoViewContent( 3483): handleEvent: pagetitlechanged
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:19.601 D/ServiceAllocator( 3483): org.mozilla.gecko.process.GeckoChildProcessServices$tab28 updateBindings: IDLE priority, 6 importance, 0 successful binds, 0 failed binds, 2 successful unbinds
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): Error
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-04-10T22:17:48.710Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1741)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1522)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1497)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.BaseSessionTest.waitForPageStop(BaseSessionTest.kt:181)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.WebNotificationTest.setup(WebNotificationTest.kt:23)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at java.lang.reflect.Method.invoke(Native Method)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2022-04-10T22:17:48.711Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.junit.rules.Verifier$1.evaluate(Verifier.java:35)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$org-mozilla-geckoview-test-rule-GeckoSessionTestRule$2(GeckoSessionTestRule.java:1451)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2$$ExternalSyntheticLambda0.run(Unknown Source)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at java.util.concurrent.FutureTask.run(FutureTask.java:237)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at android.os.Looper.loop(Looper.java:154)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2022-04-10T22:17:48.712Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at java.lang.reflect.Method.invoke(Native Method)
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - 04-10 22:17:48.576 E/GeckoSessionTestRule( 3483): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - 04-10 22:17:48.577 D/GeckoViewContent( 3483): handleEvent: DOMWindowClose
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - 04-10 22:17:48.579 D/GeckoViewConsole( 3483): onEvent GeckoView:WebExtension:List null
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - 04-10 22:17:48.581 E/GeckoSessionTestRule( 3483): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 clickNotificationParceled(org.mozilla.geckoview.test.WebNotificationTest)
[task 2022-04-10T22:17:48.713Z] 22:17:48 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.WebNotificationTest#clickNotificationParceled | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - TEST-INFO took 30343ms
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=884
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=clickNotification
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.WebNotificationTest
[task 2022-04-10T22:17:48.713Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=872
[task 2022-04-10T22:17:48.714Z] 22:17:48 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2022-04-10T22:17:48.714Z] 22:17:48 INFO - TEST-START | org.mozilla.geckoview.test.WebNotificationTest#clickNotification
Comment hidden (Intermittent Failures Robot) |
Comment 2•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Reporter | ||
Comment 3•3 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=377819739&repo=autoland
Comment hidden (Intermittent Failures Robot) |
Comment 5•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Reporter | ||
Comment 6•3 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=383108438&repo=autoland
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 9•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Reporter | ||
Comment 10•3 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=387165690&repo=autoland
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 13•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Description
•