1724262 - Intermittent org.mozilla.geckoview.test.NavigationDelegateTest.purgeHistory | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms

Status: RESOLVED INCOMPLETE

(GeckoView :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=347545408&repo=mozilla-release
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XQFuPlrCRM69yREj6PosrQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-08-05T16:40:40.126Z] 16:40:40     INFO -  Printing logcat for test:
[task 2021-08-05T16:40:40.280Z] 16:40:40     INFO -  08-05 17:40:07.626 E/GeckoSessionTestRule( 3142): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec purgeHistory(org.mozilla.geckoview.test.NavigationDelegateTest)
[task 2021-08-05T16:40:40.280Z] 16:40:40     INFO -  08-05 17:40:07.626 E/GeckoSessionTestRule( 3142): before prepareStatement purgeHistory(org.mozilla.geckoview.test.NavigationDelegateTest)
[task 2021-08-05T16:40:40.280Z] 16:40:40     INFO -  08-05 17:40:07.627 D/GeckoViewMediaControl[C]( 6586): onDisable
[task 2021-08-05T16:40:40.280Z] 16:40:40     INFO -  08-05 17:40:07.627 D/GeckoViewSelectionActionDelegate[C]( 6586): handleEvent: visibilitychange
[task 2021-08-05T16:40:40.280Z] 16:40:40     INFO -  08-05 17:40:07.627 D/GeckoViewAutofill[C]( 6586): handleEvent: pagehide
[task 2021-08-05T16:40:40.281Z] 16:40:40     INFO -  08-05 17:40:07.628 D/GeckoViewAutofill( 6586): Clearing auto-fill
[task 2021-08-05T16:40:40.281Z] 16:40:40     INFO -  08-05 17:40:07.630 E/eglCodecCommon( 3142): glUtilsParamSize: unknow param 0x00008caa
[task 2021-08-05T16:40:40.281Z] 16:40:40     INFO -  08-05 17:40:07.637 E/eglCodecCommon( 3142): glUtilsParamSize: unknow param 0x00008741
[task 2021-08-05T16:40:40.281Z] 16:40:40     INFO -  08-05 17:40:07.658 D/GeckoViewNavigation( 3142): sessionContextId=null
[task 2021-08-05T16:40:40.282Z] 16:40:40     INFO -  08-05 17:40:07.661 D/GeckoViewModule( 3142): registerListener ["GeckoViewContent:ExitFullScreen","GeckoView:ClearMatches","GeckoView:DisplayMatches","GeckoView:FindInPage","GeckoView:RestoreState","GeckoView:ScrollBy","GeckoView:ScrollTo","GeckoView:SetActive","GeckoView:SetFocused","GeckoView:UpdateInitData","GeckoView:ZoomToInput"]
[task 2021-08-05T16:40:40.282Z] 16:40:40     INFO -  08-05 17:40:07.662 D/GeckoViewNavigation( 3142): onInit
[task 2021-08-05T16:40:40.282Z] 16:40:40     INFO -  08-05 17:40:07.662 D/GeckoViewModule( 3142): registerListener ["GeckoView:GoBack","GeckoView:GoForward","GeckoView:GotoHistoryIndex","GeckoView:LoadUri","GeckoView:Reload","GeckoView:Stop","GeckoView:PurgeHistory"]
[task 2021-08-05T16:40:40.282Z] 16:40:40     INFO -  08-05 17:40:07.662 D/GeckoViewNavigation( 3142): onEnable
[task 2021-08-05T16:40:40.283Z] 16:40:40     INFO -  08-05 17:40:07.662 D/GeckoViewProcessHangMonitor( 3142): onInit
[task 2021-08-05T16:40:40.283Z] 16:40:40     INFO -  08-05 17:40:07.662 D/GeckoViewProcessHangMonitor( 3142): onEnable
[task 2021-08-05T16:40:40.283Z] 16:40:40     INFO -  08-05 17:40:07.662 D/GeckoViewModule( 3142): registerListener ["GeckoView:HangReportStop","GeckoView:HangReportWait"]
[task 2021-08-05T16:40:40.283Z] 16:40:40     INFO -  08-05 17:40:07.663 D/GeckoViewProgress( 3142): onEnable
[task 2021-08-05T16:40:40.284Z] 16:40:40     INFO -  08-05 17:40:07.663 D/GeckoSession( 3142): handleMessage GeckoView:PageStart uri=about:blank
[task 2021-08-05T16:40:40.284Z] 16:40:40     INFO -  08-05 17:40:07.663 E/GeckoSessionTestRule( 3142): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStart(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2021-08-05T16:40:40.284Z] 16:40:40     INFO -  08-05 17:40:07.663 D/GeckoViewModule( 3142): registerListener GeckoView:FlushSessionState
[task 2021-08-05T16:40:40.284Z] 16:40:40     INFO -  08-05 17:40:07.663 D/GeckoSession( 3142): handleMessage GeckoView:LocationChange uri=about:blank
[task 2021-08-05T16:40:40.285Z] 16:40:40     INFO -  08-05 17:40:07.663 E/GeckoSessionTestRule( 3142): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String,java.util.List)
[task 2021-08-05T16:40:40.285Z] 16:40:40     INFO -  08-05 17:40:07.663 E/GeckoSessionTestRule( 3142): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2021-08-05T16:40:40.285Z] 16:40:40     INFO -  08-05 17:40:07.663 E/GeckoSessionTestRule( 3142): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoBack(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-08-05T16:40:40.286Z] 16:40:40     INFO -  08-05 17:40:07.663 E/GeckoSessionTestRule( 3142): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoForward(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-08-05T16:40:40.286Z] 16:40:40     INFO -  08-05 17:40:07.663 D/GeckoSession( 3142): handleMessage GeckoView:PageStop uri=null
[task 2021-08-05T16:40:40.286Z] 16:40:40     INFO -  08-05 17:40:07.663 E/GeckoSessionTestRule( 3142): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStop(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-08-05T16:40:40.286Z] 16:40:40     INFO -  08-05 17:40:07.664 D/GeckoViewSettings( 3142): onInit
[task 2021-08-05T16:40:40.286Z] 16:40:40     INFO -  08-05 17:40:07.664 E/GeckoSessionTestRule( 3142): after prepareStatement
[task 2021-08-05T16:40:40.287Z] 16:40:40     INFO -  08-05 17:40:07.664 D/GeckoViewModule( 3142): registerListener ["GeckoView:GetUserAgent"]
[task 2021-08-05T16:40:40.287Z] 16:40:40     INFO -  08-05 17:40:07.664 D/GeckoViewSettings( 3142): 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 2021-08-05T16:40:40.287Z] 16:40:40     INFO -  08-05 17:40:07.664 D/GeckoViewModule( 3142): registerListener ["GeckoView:WebExtension:SetTabActive"]
[task 2021-08-05T16:40:40.287Z] 16:40:40     INFO -  08-05 17:40:07.664 D/GeckoViewModule( 3142): registerListener ["ContentBlocking:RequestLog"]
[task 2021-08-05T16:40:40.287Z] 16:40:40     INFO -  08-05 17:40:07.665 D/GeckoViewModule( 3142): enableQueuing true
[task 2021-08-05T16:40:40.288Z] 16:40:40     INFO -  08-05 17:40:07.665 D/GeckoViewMediaControl( 3142): onEnable
[task 2021-08-05T16:40:40.288Z] 16:40:40     INFO -  08-05 17:40:07.665 D/GeckoViewModule( 3142): 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 2021-08-05T16:40:40.288Z] 16:40:40     INFO -  08-05 17:40:07.666 I/GeckoSession( 3142): zerdatime 188286 - chrome startup finished
[task 2021-08-05T16:40:40.289Z] 16:40:40     INFO -  08-05 17:40:07.668 D/GeckoViewModule( 3142): dispatch GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/hello.html","flags":0,"headerFilter":1}
[task 2021-08-05T16:40:40.289Z] 16:40:40     INFO -  08-05 17:40:07.668 D/GeckoViewNavigation( 3142): onEvent: event=GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/hello.html","flags":0,"headerFilter":1}
[task 2021-08-05T16:40:40.289Z] 16:40:40     INFO -  08-05 17:40:07.671 D/GeckoViewSelectionActionDelegate[C]( 6586): handleEvent: visibilitychange
[task 2021-08-05T16:40:40.289Z] 16:40:40     INFO -  08-05 17:40:07.671 D/GeckoViewSettings[C]( 6586): receiveMessage: SettingsUpdate
[task 2021-08-05T16:40:40.289Z] 16:40:40     INFO -  08-05 17:40:07.673 D/GeckoViewAutofill[C]( 6586): onInit
[task 2021-08-05T16:40:40.289Z] 16:40:40     INFO -  08-05 17:40:07.673 D/GeckoViewXUL( 3142): receiveMessage GeckoView:ContentModuleLoaded {"module":"SessionStateAggregator"}
[task 2021-08-05T16:40:40.290Z] 16:40:40     INFO -  08-05 17:40:07.674 D/GeckoViewMediaControl[C]( 6586): onEnable
[task 2021-08-05T16:40:40.290Z] 16:40:40     INFO -  08-05 17:40:07.674 D/GeckoViewXUL( 3142): receiveMessage GeckoView:ContentModuleLoaded {"module":"GeckoViewAutofill"}
[task 2021-08-05T16:40:40.290Z] 16:40:40     INFO -  08-05 17:40:07.674 D/GeckoViewMediaControl[C]( 6586): onEnable
[task 2021-08-05T16:40:40.290Z] 16:40:40     INFO -  08-05 17:40:07.674 D/GeckoViewXUL( 3142): receiveMessage GeckoView:ContentModuleLoaded {"module":"GeckoViewMediaControl"}
[task 2021-08-05T16:40:40.290Z] 16:40:40     INFO -  08-05 17:40:07.675 D/GeckoViewModule( 3142): enableQueuing false
[task 2021-08-05T16:40:40.291Z] 16:40:40     INFO -  08-05 17:40:07.675 D/GeckoViewModule( 3142): dispatchQueued
[task 2021-08-05T16:40:40.291Z] 16:40:40     INFO -  08-05 17:40:07.679 D/GeckoViewProgress( 3142): ProgressTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK
[task 2021-08-05T16:40:40.291Z] 16:40:40     INFO -  08-05 17:40:07.679 D/GeckoViewProgress( 3142): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello.html
[task 2021-08-05T16:40:40.291Z] 16:40:40     INFO -  08-05 17:40:07.679 D/GeckoViewProgress( 3142): ProgressTracker start http://localhost:4245/assets/www/hello.html
[task 2021-08-05T16:40:40.291Z] 16:40:40     INFO -  08-05 17:40:07.679 D/GeckoViewProgress( 3142): ProgressTracker updateProgress
[task 2021-08-05T16:40:40.292Z] 16:40:40     INFO -  08-05 17:40:07.679 D/GeckoViewProgress( 3142): 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 2021-08-05T16:40:40.292Z] 16:40:40     INFO -  08-05 17:40:07.679 D/GeckoSession( 3142): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-08-05T16:40:40.292Z] 16:40:40     INFO -  08-05 17:40:07.680 D/GeckoViewProgress( 3142): StateTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK loadType=1
[task 2021-08-05T16:40:40.292Z] 16:40:40     INFO -  08-05 17:40:07.680 D/GeckoSession( 3142): handleMessage GeckoView:PageStart uri=http://localhost:4245/assets/www/hello.html
[task 2021-08-05T16:40:40.292Z] 16:40:40     INFO -  08-05 17:40:07.733 D/GeckoViewSelectionActionDelegate[C]( 6586): handleEvent: visibilitychange
[task 2021-08-05T16:40:40.293Z] 16:40:40     INFO -  08-05 17:40:07.733 D/GeckoViewAutofill[C]( 6586): handleEvent: pagehide
[task 2021-08-05T16:40:40.293Z] 16:40:40     INFO -  08-05 17:40:07.733 D/GeckoViewAutofill( 6586): Clearing auto-fill
[task 2021-08-05T16:40:40.293Z] 16:40:40     INFO -  08-05 17:40:07.745 D/GeckoViewContentDelegateChild[C]( 6586): handleEvent: DOMContentLoaded
[task 2021-08-05T16:40:40.293Z] 16:40:40     INFO -  08-05 17:40:07.747 D/GeckoViewProgressDelegate[C]( 6586): handleEvent: DOMContentLoaded
[task 2021-08-05T16:40:40.293Z] 16:40:40     INFO -  08-05 17:40:07.754 D/GeckoViewProgressDelegate[C]( 6586): handleEvent: pageshow
[task 2021-08-05T16:40:40.293Z] 16:40:40     INFO -  08-05 17:40:07.754 D/GeckoViewContent[C]( 6586): handleEvent: pageshow
[task 2021-08-05T16:40:40.293Z] 16:40:40     INFO -  08-05 17:40:07.754 D/GeckoViewAutofill[C]( 6586): handleEvent: pageshow
[task 2021-08-05T16:40:40.294Z] 16:40:40     INFO -  08-05 17:40:08.788 D/GeckoViewNavigation( 3142): onLocationChange
[task 2021-08-05T16:40:40.294Z] 16:40:40     INFO -  08-05 17:40:08.789 D/GeckoSession( 3142): handleMessage GeckoView:LocationChange uri=http://localhost:4245/assets/www/hello.html
[task 2021-08-05T16:40:40.294Z] 16:40:40     INFO -  08-05 17:40:08.789 D/GeckoViewProgress( 3142): SecurityTracker onLocationChange: location=http://localhost:4245/assets/www/hello.html, flags=0
[task 2021-08-05T16:40:40.294Z] 16:40:40     INFO -  08-05 17:40:08.789 D/GeckoViewProgress( 3142): ProgressTracker onLocationChange: location=http://localhost:4245/assets/www/hello.html, flags=0
[task 2021-08-05T16:40:40.294Z] 16:40:40     INFO -  08-05 17:40:08.789 D/GeckoViewProgress( 3142): ProgressTracker changeLocation http://localhost:4245/assets/www/hello.html
[task 2021-08-05T16:40:40.294Z] 16:40:40     INFO -  08-05 17:40:08.789 D/GeckoViewProgress( 3142): onSecurityChange
[task 2021-08-05T16:40:40.295Z] 16:40:40     INFO -  08-05 17:40:08.789 D/GeckoViewContent( 3142): handleEvent: pagetitlechanged
[task 2021-08-05T16:40:40.295Z] 16:40:40     INFO -  08-05 17:40:08.790 D/GeckoViewProgress( 3142): receiveMessage: DOMContentLoaded
[task 2021-08-05T16:40:40.295Z] 16:40:40     INFO -  08-05 17:40:08.790 D/GeckoViewProgress( 3142): ProgressTracker handleEvent: DOMContentLoaded
[task 2021-08-05T16:40:40.295Z] 16:40:40     INFO -  08-05 17:40:08.790 D/GeckoViewProgress( 3142): ProgressTracker updateProgress
[task 2021-08-05T16:40:40.296Z] 16:40:40     INFO -  08-05 17:40:08.790 D/GeckoViewProgress( 3142): ProgressTracker updateProgress data={"prev":15,"uri":"http://localhost:4245/assets/www/hello.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":true} progress=55
[task 2021-08-05T16:40:40.296Z] 16:40:40     INFO -  08-05 17:40:08.792 D/GeckoViewProgress( 3142): receiveMessage: pageshow
[task 2021-08-05T16:40:40.296Z] 16:40:40     INFO -  08-05 17:40:08.792 D/GeckoViewProgress( 3142): ProgressTracker handleEvent: pageshow
[task 2021-08-05T16:40:40.296Z] 16:40:40     INFO -  08-05 17:40:08.792 D/GeckoViewProgress( 3142): ProgressTracker updateProgress
[task 2021-08-05T16:40:40.296Z] 16:40:40     INFO -  08-05 17:40:08.792 D/GeckoViewProgress( 3142): ProgressTracker updateProgress data={"prev":55,"uri":"http://localhost:4245/assets/www/hello.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":true,"parsed":true} progress=100
[task 2021-08-05T16:40:40.296Z] 16:40:40     INFO -  08-05 17:40:08.793 D/GeckoViewProgress( 3142): ProgressTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.793 D/GeckoViewProgress( 3142): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello.html
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.793 D/GeckoViewProgress( 3142): ProgressTracker stop
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.793 D/GeckoViewProgress( 3142): ProgressTracker updateProgress
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.793 D/GeckoViewProgress( 3142): StateTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK loadType=1
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.794 D/GeckoViewModule( 3142): dispatch GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/hello2.html","flags":0,"headerFilter":1}
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.794 D/GeckoViewNavigation( 3142): onEvent: event=GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/hello2.html","flags":0,"headerFilter":1}
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.796 D/GeckoSession( 3142): handleMessage GeckoView:SecurityChanged uri=null
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.796 D/GeckoSession( 3142): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-08-05T16:40:40.297Z] 16:40:40     INFO -  08-05 17:40:08.796 D/WebExtension( 3142): handleMessage GeckoView:WebExtension:Connect
[task 2021-08-05T16:40:40.298Z] 16:40:40     INFO -  08-05 17:40:08.798 D/GeckoViewProgress( 3142): ProgressTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK
[task 2021-08-05T16:40:40.298Z] 16:40:40     INFO -  08-05 17:40:08.798 D/GeckoViewProgress( 3142): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello2.html
[task 2021-08-05T16:40:40.298Z] 16:40:40     INFO -  08-05 17:40:08.798 D/GeckoViewProgress( 3142): ProgressTracker start http://localhost:4245/assets/www/hello2.html
[task 2021-08-05T16:40:40.298Z] 16:40:40     INFO -  08-05 17:40:08.798 D/GeckoViewProgress( 3142): ProgressTracker updateProgress
[task 2021-08-05T16:40:40.298Z] 16:40:40     INFO -  08-05 17:40:08.798 D/GeckoViewProgress( 3142): ProgressTracker updateProgress data={"prev":0,"uri":"http://localhost:4245/assets/www/hello2.html","locationChange":false,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":false} progress=15
[task 2021-08-05T16:40:40.298Z] 16:40:40     INFO -  08-05 17:40:08.798 D/GeckoViewProgress( 3142): StateTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK loadType=1
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.800 E/Web Content( 6586): [JavaScript Error: "TypeError: NetworkError when attempting to fetch resource."]
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.800 D/GeckoSession( 3142): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.800 D/GeckoSession( 3142): handleMessage GeckoView:PageStop uri=null
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.800 D/GeckoSession( 3142): handleMessage GeckoView:StateUpdated uri=null
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.800 W/GeckoSession( 3142): No history entries found.
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.801 D/GeckoSession( 3142): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.801 D/GeckoSession( 3142): handleMessage GeckoView:PageStart uri=http://localhost:4245/assets/www/hello2.html
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.805 D/GeckoViewSelectionActionDelegate[C]( 6586): handleEvent: visibilitychange
[task 2021-08-05T16:40:40.299Z] 16:40:40     INFO -  08-05 17:40:08.805 D/GeckoViewAutofill[C]( 6586): handleEvent: pagehide
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.805 D/GeckoViewAutofill( 6586): Clearing auto-fill
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.813 D/GeckoViewNavigation( 3142): onLocationChange
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.813 D/GeckoSession( 3142): handleMessage GeckoView:LocationChange uri=http://localhost:4245/assets/www/hello2.html
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.813 D/GeckoViewProgress( 3142): SecurityTracker onLocationChange: location=http://localhost:4245/assets/www/hello2.html, flags=0
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.813 D/GeckoViewProgress( 3142): ProgressTracker onLocationChange: location=http://localhost:4245/assets/www/hello2.html, flags=0
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.813 D/GeckoViewProgress( 3142): ProgressTracker changeLocation http://localhost:4245/assets/www/hello2.html
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.813 D/GeckoViewProgress( 3142): onSecurityChange
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.817 D/GeckoViewContent( 3142): handleEvent: pagetitlechanged
[task 2021-08-05T16:40:40.300Z] 16:40:40     INFO -  08-05 17:40:08.817 D/GeckoViewContentDelegateChild[C]( 6586): handleEvent: DOMContentLoaded
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.817 D/GeckoViewProgressDelegate[C]( 6586): handleEvent: DOMContentLoaded
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.818 D/GeckoViewProgress( 3142): receiveMessage: DOMContentLoaded
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.818 D/GeckoViewProgress( 3142): ProgressTracker handleEvent: DOMContentLoaded
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.818 D/GeckoViewProgress( 3142): ProgressTracker updateProgress
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.818 D/GeckoViewProgress( 3142): ProgressTracker updateProgress data={"prev":15,"uri":"http://localhost:4245/assets/www/hello2.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":true} progress=55
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.818 D/GeckoViewModule( 3142): dispatch GeckoView:PurgeHistory, data=null
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.818 D/GeckoViewNavigation( 3142): onEvent: event=GeckoView:PurgeHistory, data=null
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.820 D/GeckoSession( 3142): handleMessage GeckoView:SecurityChanged uri=null
[task 2021-08-05T16:40:40.301Z] 16:40:40     INFO -  08-05 17:40:08.821 D/GeckoSession( 3142): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.822 D/GeckoViewProgressDelegate[C]( 6586): handleEvent: pageshow
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.822 D/GeckoViewContent[C]( 6586): handleEvent: pageshow
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.822 D/GeckoViewAutofill[C]( 6586): handleEvent: pageshow
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.824 D/WebExtension( 3142): handleMessage GeckoView:WebExtension:Connect
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.824 D/GeckoViewProgress( 3142): receiveMessage: pageshow
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.824 D/GeckoViewProgress( 3142): ProgressTracker handleEvent: pageshow
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.824 D/GeckoViewProgress( 3142): ProgressTracker updateProgress
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.825 D/GeckoViewProgress( 3142): ProgressTracker updateProgress data={"prev":55,"uri":"http://localhost:4245/assets/www/hello2.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":true,"parsed":true} progress=100
[task 2021-08-05T16:40:40.302Z] 16:40:40     INFO -  08-05 17:40:08.825 D/GeckoSession( 3142): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-08-05T16:40:40.303Z] 16:40:40     INFO -  08-05 17:40:08.828 D/GeckoViewProgress( 3142): ProgressTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK
[task 2021-08-05T16:40:40.303Z] 16:40:40     INFO -  08-05 17:40:08.828 D/GeckoViewProgress( 3142): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello2.html
[task 2021-08-05T16:40:40.303Z] 16:40:40     INFO -  08-05 17:40:08.828 D/GeckoViewProgress( 3142): ProgressTracker stop
[task 2021-08-05T16:40:40.303Z] 16:40:40     INFO -  08-05 17:40:08.828 D/GeckoViewProgress( 3142): ProgressTracker updateProgress
[task 2021-08-05T16:40:40.303Z] 16:40:40     INFO -  08-05 17:40:08.828 D/GeckoViewProgress( 3142): StateTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK loadType=1
[task 2021-08-05T16:40:40.303Z] 16:40:40     INFO -  08-05 17:40:08.829 D/GeckoSession( 3142): handleMessage GeckoView:PageStop uri=null
[task 2021-08-05T16:40:40.303Z] 16:40:40     INFO -  08-05 17:40:09.829 E/GeckoConsole( 3142): [JavaScript Error: "NS_ERROR_FILE_NOT_FOUND: " {file: "resource://gre/modules/SessionStoreFunctions.jsm" line: 6}]
[task 2021-08-05T16:40:40.303Z] 16:40:40     INFO -  08-05 17:40:09.829 E/GeckoConsole( 3142): SSF_updateSessionStoreForWindow@resource://gre/modules/SessionStoreFunctions.jsm:6:539
[task 2021-08-05T16:40:40.304Z] 16:40:40     INFO -  08-05 17:40:09.829 E/GeckoConsole( 3142): UpdateSessionStoreForStorage@resource://gre/modules/SessionStoreFunctions.jsm:3:125
[task 2021-08-05T16:40:40.304Z] 16:40:40     INFO -  08-05 17:40:09.839 D/GeckoSession( 3142): handleMessage GeckoView:StateUpdated uri=null
[task 2021-08-05T16:40:40.304Z] 16:40:40     INFO -  08-05 17:40:14.104 E/GeckoConsole( 3142): [JavaScript Error: "NS_ERROR_FILE_NOT_FOUND: " {file: "resource://gre/modules/SessionStoreFunctions.jsm" line: 6}]
[task 2021-08-05T16:40:40.304Z] 16:40:40     INFO -  08-05 17:40:14.104 E/GeckoConsole( 3142): SSF_updateSessionStoreForWindow@resource://gre/modules/SessionStoreFunctions.jsm:6:539
[task 2021-08-05T16:40:40.304Z] 16:40:40     INFO -  08-05 17:40:14.104 E/GeckoConsole( 3142): UpdateSessionStoreForStorage@resource://gre/modules/SessionStoreFunctions.jsm:3:125
[task 2021-08-05T16:40:40.304Z] 16:40:40     INFO -  08-05 17:40:16.109 E/GeckoConsole( 3142): [JavaScript Error: "NS_ERROR_FILE_NOT_FOUND: " {file: "resource://gre/modules/SessionStoreFunctions.jsm" line: 6}]
[task 2021-08-05T16:40:40.305Z] 16:40:40     INFO -  08-05 17:40:16.109 E/GeckoConsole( 3142): SSF_updateSessionStoreForWindow@resource://gre/modules/SessionStoreFunctions.jsm:6:539
[task 2021-08-05T16:40:40.305Z] 16:40:40     INFO -  08-05 17:40:16.109 E/GeckoConsole( 3142): UpdateSessionStoreForStorage@resource://gre/modules/SessionStoreFunctions.jsm:3:125
[task 2021-08-05T16:40:40.305Z] 16:40:40     INFO -  08-05 17:40:17.644 E/GeckoConsole( 3142): [JavaScript Error: "NS_ERROR_FILE_NOT_FOUND: " {file: "resource://gre/modules/SessionStoreFunctions.jsm" line: 6}]
[task 2021-08-05T16:40:40.305Z] 16:40:40     INFO -  08-05 17:40:17.644 E/GeckoConsole( 3142): SSF_updateSessionStoreForWindow@resource://gre/modules/SessionStoreFunctions.jsm:6:539
[task 2021-08-05T16:40:40.305Z] 16:40:40     INFO -  08-05 17:40:17.644 E/GeckoConsole( 3142): UpdateSessionStoreForStorage@resource://gre/modules/SessionStoreFunctions.jsm:3:125
[task 2021-08-05T16:40:40.305Z] 16:40:40     INFO -  08-05 17:40:17.661 E/GeckoConsole( 3142): [JavaScript Error: "NS_ERROR_FILE_NOT_FOUND: " {file: "resource://gre/modules/SessionStoreFunctions.jsm" line: 6}]
[task 2021-08-05T16:40:40.305Z] 16:40:40     INFO -  08-05 17:40:17.661 E/GeckoConsole( 3142): SSF_updateSessionStoreForWindow@resource://gre/modules/SessionStoreFunctions.jsm:6:539
[task 2021-08-05T16:40:40.305Z] 16:40:40     INFO -  08-05 17:40:17.661 E/GeckoConsole( 3142): UpdateSessionStoreForStorage@resource://gre/modules/SessionStoreFunctions.jsm:3:125
[task 2021-08-05T16:40:40.306Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): Error
[task 2021-08-05T16:40:40.306Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-08-05T16:40:40.306Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:52)
[task 2021-08-05T16:40:40.306Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-08-05T16:40:40.306Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-08-05T16:40:40.306Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:155)
[task 2021-08-05T16:40:40.306Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1591)
[task 2021-08-05T16:40:40.306Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1533)
[task 2021-08-05T16:40:40.307Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1486)
[task 2021-08-05T16:40:40.307Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.mozilla.geckoview.test.NavigationDelegateTest.purgeHistory(NavigationDelegateTest.kt:2157)
[task 2021-08-05T16:40:40.307Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-08-05T16:40:40.307Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-08-05T16:40:40.307Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-08-05T16:40:40.307Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-08-05T16:40:40.307Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1317)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$cmP_QJg-X16GIlt8KIQd32egmfU.run(lambda)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at android.os.Looper.loop(Looper.java:154)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-08-05T16:40:40.308Z] 16:40:40     INFO -  08-05 17:40:39.841 E/GeckoSessionTestRule( 3142): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  08-05 17:40:39.907 D/GeckoViewContent( 3142): handleEvent: DOMWindowClose
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  08-05 17:40:39.907 D/GeckoViewConsole( 3142): onEvent GeckoView:WebExtension:List null
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  08-05 17:40:39.909 E/GeckoSessionTestRule( 3142): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 purgeHistory(org.mozilla.geckoview.test.NavigationDelegateTest)
[task 2021-08-05T16:40:40.309Z] 16:40:40  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.NavigationDelegateTest.purgeHistory | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  TEST-INFO took 32451ms
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=795
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=safebrowsingUnwanted
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.NavigationDelegateTest
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=382
[task 2021-08-05T16:40:40.309Z] 16:40:40     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1

Comment 1

[Intermittent Failures Robot]

1 failures in 2829 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1724262&startday=2021-08-02&endday=2021-08-08&tree=all

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

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