1744372 - Intermittent org.mozilla.geckoview.test.OrientationDelegateTest#orientationLockedAlready | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms

Status: RESOLVED FIXED

(GeckoView :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-12-04T01:43:06.297Z] 01:43:06     INFO -  Printing logcat for test:
[task 2021-12-04T01:43:06.357Z] 01:43:06     INFO -  12-04 01:42:35.219 E/GeckoSessionTestRule( 3454): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec orientationLockedAlready(org.mozilla.geckoview.test.OrientationDelegateTest)
[task 2021-12-04T01:43:06.357Z] 01:43:06     INFO -  12-04 01:42:35.219 E/GeckoSessionTestRule( 3454): before prepareStatement orientationLockedAlready(org.mozilla.geckoview.test.OrientationDelegateTest)
[task 2021-12-04T01:43:06.357Z] 01:43:06     INFO -  12-04 01:42:35.222 E/eglCodecCommon( 3454): glUtilsParamSize: unknow param 0x00008caa
[task 2021-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.229 E/eglCodecCommon( 3454): glUtilsParamSize: unknow param 0x00008741
[task 2021-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.245 D/GeckoViewNavigation( 3454): sessionContextId=null
[task 2021-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.249 D/GeckoViewModule( 3454): 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-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.250 D/GeckoViewNavigation( 3454): onInit
[task 2021-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.250 D/GeckoViewModule( 3454): registerListener ["GeckoView:GoBack","GeckoView:GoForward","GeckoView:GotoHistoryIndex","GeckoView:LoadUri","GeckoView:Reload","GeckoView:Stop","GeckoView:PurgeHistory"]
[task 2021-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.250 D/GeckoViewNavigation( 3454): onEnable
[task 2021-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.251 D/GeckoViewProcessHangMonitor( 3454): onInit
[task 2021-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.251 D/GeckoViewProcessHangMonitor( 3454): onEnable
[task 2021-12-04T01:43:06.360Z] 01:43:06     INFO -  12-04 01:42:35.251 D/GeckoViewModule( 3454): registerListener ["GeckoView:HangReportStop","GeckoView:HangReportWait"]
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.251 D/GeckoViewProgress( 3454): onEnable
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.251 D/GeckoSession( 3454): handleMessage GeckoView:PageStart uri=about:blank
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 E/GeckoSessionTestRule( 3454): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStart(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 D/GeckoSession( 3454): handleMessage GeckoView:LocationChange uri=about:blank
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 E/GeckoSessionTestRule( 3454): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String,java.util.List)
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 E/GeckoSessionTestRule( 3454): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 D/GeckoViewModule( 3454): registerListener GeckoView:FlushSessionState
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 E/GeckoSessionTestRule( 3454): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoBack(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 E/GeckoSessionTestRule( 3454): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoForward(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 D/GeckoSession( 3454): handleMessage GeckoView:PageStop uri=null
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 E/GeckoSessionTestRule( 3454): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStop(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 E/GeckoSessionTestRule( 3454): after prepareStatement
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 D/GeckoViewSettings( 3454): onInit
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.252 D/GeckoViewModule( 3454): registerListener ["GeckoView:GetUserAgent"]
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.253 D/GeckoViewSettings( 3454): 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-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.253 D/GeckoViewModule( 3454): registerListener ["GeckoView:WebExtension:SetTabActive"]
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.253 D/GeckoViewModule( 3454): registerListener ["ContentBlocking:RequestLog"]
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.254 D/GeckoViewModule( 3454): enableQueuing true
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.254 D/GeckoViewMediaControl( 3454): onEnable
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.254 D/GeckoViewModule( 3454): 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-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.255 D/GeckoViewSelectionActionDelegate[C]( 7057): handleEvent: visibilitychange
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.256 I/GeckoSession( 3454): zerdatime 204258 - chrome startup finished
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.257 D/GeckoViewSettings[C]( 7057): receiveMessage: SettingsUpdate
[task 2021-12-04T01:43:06.361Z] 01:43:06     INFO -  12-04 01:42:35.258 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"7d3a6f67-0677-4345-8802-916c4779a5ec","args":{"oldPrefs":{},"newPrefs":{"dom.screenorientation.allow-lock":true}},"type":"SetPrefs"}}
[task 2021-12-04T01:43:06.362Z] 01:43:06     INFO -  12-04 01:42:35.258 W/GeckoEditableChild( 7057): No editable parent
[task 2021-12-04T01:43:06.362Z] 01:43:06     INFO -  12-04 01:42:35.259 D/GeckoViewXUL( 3454): receiveMessage GeckoView:ContentModuleLoaded {"module":"SessionStateAggregator"}
[task 2021-12-04T01:43:06.362Z] 01:43:06     INFO -  12-04 01:42:35.259 D/GeckoViewMediaControl[C]( 7057): onEnable
[task 2021-12-04T01:43:06.362Z] 01:43:06     INFO -  12-04 01:42:35.259 D/GeckoViewMediaControl[C]( 7057): onEnable
[task 2021-12-04T01:43:06.362Z] 01:43:06     INFO -  12-04 01:42:35.260 D/GeckoViewXUL( 3454): receiveMessage GeckoView:ContentModuleLoaded {"module":"GeckoViewMediaControl"}
[task 2021-12-04T01:43:06.362Z] 01:43:06     INFO -  12-04 01:42:35.261 D/GeckoViewModule( 3454): enableQueuing false
[task 2021-12-04T01:43:06.362Z] 01:43:06     INFO -  12-04 01:42:35.261 D/GeckoViewModule( 3454): dispatchQueued
[task 2021-12-04T01:43:06.362Z] 01:43:06     INFO -  12-04 01:42:35.264 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"a0e5a2bc-a362-470a-b22e-b065e26bce26","args":{"oldPrefs":{"dom.screenorientation.allow-lock":false},"newPrefs":{"full-screen-api.allow-trusted-requests-only":false}},"type":"SetPrefs"}}
[task 2021-12-04T01:43:06.363Z] 01:43:06     INFO -  12-04 01:42:35.304 D/GeckoViewModule( 3454): dispatch GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/fullscreen.html","flags":0,"headerFilter":1}
[task 2021-12-04T01:43:06.363Z] 01:43:06     INFO -  12-04 01:42:35.304 D/GeckoViewNavigation( 3454): onEvent: event=GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/fullscreen.html","flags":0,"headerFilter":1}
[task 2021-12-04T01:43:06.363Z] 01:43:06     INFO -  12-04 01:42:35.310 D/GeckoViewProgress( 3454): ProgressTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK
[task 2021-12-04T01:43:06.363Z] 01:43:06     INFO -  12-04 01:42:35.310 D/GeckoViewProgress( 3454): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-04T01:43:06.363Z] 01:43:06     INFO -  12-04 01:42:35.311 D/GeckoViewProgress( 3454): ProgressTracker start http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-04T01:43:06.363Z] 01:43:06     INFO -  12-04 01:42:35.311 D/GeckoViewProgress( 3454): ProgressTracker updateProgress
[task 2021-12-04T01:43:06.363Z] 01:43:06     INFO -  12-04 01:42:35.311 D/GeckoViewProgress( 3454): ProgressTracker updateProgress data={"prev":0,"uri":"http://localhost:4245/assets/www/fullscreen.html","locationChange":false,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":false} progress=15
[task 2021-12-04T01:43:06.363Z] 01:43:06     INFO -  12-04 01:42:35.311 D/GeckoSession( 3454): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.311 D/GeckoViewProgress( 3454): StateTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK loadType=1
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.311 D/GeckoSession( 3454): handleMessage GeckoView:PageStart uri=http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.317 D/GeckoViewSelectionActionDelegate[C]( 7057): handleEvent: visibilitychange
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.317 D/GeckoViewAutoFill[C]( 7057): handleEvent: pagehide
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.317 D/GeckoViewAutofill( 7057): Clearing auto-fill
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.322 W/Web Content( 7057): [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/fullscreen.html" line: 0}]
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.322 D/GeckoViewNavigation( 3454): onLocationChange
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.323 D/GeckoSession( 3454): handleMessage GeckoView:LocationChange uri=http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-04T01:43:06.364Z] 01:43:06     INFO -  12-04 01:42:35.323 D/GeckoViewProgress( 3454): SecurityTracker onLocationChange: location=http://localhost:4245/assets/www/fullscreen.html, flags=0
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.323 D/GeckoViewProgress( 3454): ProgressTracker onLocationChange: location=http://localhost:4245/assets/www/fullscreen.html, flags=0
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.324 D/GeckoViewProgress( 3454): ProgressTracker changeLocation http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.324 D/GeckoViewProgress( 3454): onSecurityChange
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.324 D/GeckoSession( 3454): handleMessage GeckoView:SecurityChanged uri=null
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.328 D/GeckoViewContent( 3454): handleEvent: pagetitlechanged
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.328 D/GeckoViewContentDelegateChild[C]( 7057): handleEvent: DOMContentLoaded
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.329 D/GeckoViewProgressDelegate[C]( 7057): handleEvent: DOMContentLoaded
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.329 D/GeckoViewProgress( 3454): receiveMessage: DOMContentLoaded
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.329 D/GeckoViewProgress( 3454): ProgressTracker handleEvent: DOMContentLoaded
[task 2021-12-04T01:43:06.365Z] 01:43:06     INFO -  12-04 01:42:35.329 D/GeckoViewProgress( 3454): ProgressTracker updateProgress
[task 2021-12-04T01:43:06.366Z] 01:43:06     INFO -  12-04 01:42:35.329 D/GeckoViewProgress( 3454): ProgressTracker updateProgress data={"prev":15,"uri":"http://localhost:4245/assets/www/fullscreen.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":true} progress=55
[task 2021-12-04T01:43:06.366Z] 01:43:06     INFO -  12-04 01:42:35.330 D/GeckoSession( 3454): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-12-04T01:43:06.366Z] 01:43:06     INFO -  12-04 01:42:35.336 D/GeckoViewProgressDelegate[C]( 7057): handleEvent: pageshow
[task 2021-12-04T01:43:06.366Z] 01:43:06     INFO -  12-04 01:42:35.336 D/GeckoViewAutoFill[C]( 7057): handleEvent: pageshow
[task 2021-12-04T01:43:06.366Z] 01:43:06     INFO -  12-04 01:42:35.337 D/GeckoViewContent[C]( 7057): handleEvent: pageshow
[task 2021-12-04T01:43:06.366Z] 01:43:06     INFO -  12-04 01:42:35.338 D/WebExtension( 3454): handleMessage GeckoView:WebExtension:Connect
[task 2021-12-04T01:43:06.366Z] 01:43:06     INFO -  12-04 01:42:35.339 D/GeckoViewProgress( 3454): receiveMessage: pageshow
[task 2021-12-04T01:43:06.366Z] 01:43:06     INFO -  12-04 01:42:35.339 D/GeckoViewProgress( 3454): ProgressTracker handleEvent: pageshow
[task 2021-12-04T01:43:06.367Z] 01:43:06     INFO -  12-04 01:42:35.339 D/GeckoViewProgress( 3454): ProgressTracker updateProgress
[task 2021-12-04T01:43:06.367Z] 01:43:06     INFO -  12-04 01:42:35.339 D/GeckoViewProgress( 3454): ProgressTracker updateProgress data={"prev":55,"uri":"http://localhost:4245/assets/www/fullscreen.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":true,"parsed":true} progress=100
[task 2021-12-04T01:43:06.367Z] 01:43:06     INFO -  12-04 01:42:35.339 D/GeckoSession( 3454): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-12-04T01:43:06.367Z] 01:43:06     INFO -  12-04 01:42:35.340 D/GeckoViewProgress( 3454): ProgressTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK
[task 2021-12-04T01:43:06.367Z] 01:43:06     INFO -  12-04 01:42:35.340 D/GeckoViewProgress( 3454): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-04T01:43:06.367Z] 01:43:06     INFO -  12-04 01:42:35.340 D/GeckoViewProgress( 3454): ProgressTracker stop
[task 2021-12-04T01:43:06.367Z] 01:43:06     INFO -  12-04 01:42:35.340 D/GeckoViewProgress( 3454): ProgressTracker updateProgress
[task 2021-12-04T01:43:06.368Z] 01:43:06     INFO -  12-04 01:42:35.341 D/GeckoViewProgress( 3454): StateTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK loadType=1
[task 2021-12-04T01:43:06.368Z] 01:43:06     INFO -  12-04 01:42:35.341 D/GeckoSession( 3454): handleMessage GeckoView:PageStop uri=null
[task 2021-12-04T01:43:06.368Z] 01:43:06     INFO -  12-04 01:42:35.342 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"c73befa1-7171-49a9-9f38-e9da205aa3ae","eval":"this['ee0255fc-2e53-4774-9902-d73625e8326f'] = document.querySelector('#fullscreen').requestFullscreen(); true"}}
[task 2021-12-04T01:43:06.368Z] 01:43:06     INFO -  12-04 01:42:35.343 D/GeckoViewContentDelegateChild[C]( 7057): handleEvent: MozDOMFullscreen:Request
[task 2021-12-04T01:43:06.368Z] 01:43:06     INFO -  12-04 01:42:35.344 D/GeckoViewContentDelegateParent( 3454): receiveMessage: GeckoView:DOMFullscreenRequest {"data":{},"json":{},"name":"GeckoView:DOMFullscreenRequest","sync":false,"target":{}}
[task 2021-12-04T01:43:06.369Z] 01:43:06     INFO -  12-04 01:42:35.346 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"4f9af067-694c-4bea-86b0-8b91ed57c2f8","eval":"this['ee0255fc-2e53-4774-9902-d73625e8326f']"}}
[task 2021-12-04T01:43:06.369Z] 01:43:06     INFO -  12-04 01:42:35.424 D/GeckoViewContent( 3454): handleEvent: MozDOMFullscreen:Entered
[task 2021-12-04T01:43:06.369Z] 01:43:06     INFO -  12-04 01:42:35.426 D/GeckoViewContent[C]( 7057): receiveMessage: GeckoView:DOMFullscreenEntered
[task 2021-12-04T01:43:06.369Z] 01:43:06     INFO -  12-04 01:42:35.426 D/GeckoViewContentDelegateChild[C]( 7057): handleEvent: MozDOMFullscreen:Entered
[task 2021-12-04T01:43:06.369Z] 01:43:06     INFO -  12-04 01:42:35.427 D/GeckoViewMediaControl[C]( 7057): handleEvent: MozDOMFullscreen:Entered
[task 2021-12-04T01:43:06.369Z] 01:43:06     INFO -  12-04 01:42:35.427 D/GeckoViewMediaControl[C]( 7057): handleFullscreenChanged
[task 2021-12-04T01:43:06.369Z] 01:43:06     INFO -  12-04 01:42:35.427 D/GeckoViewMediaControl[C]( 7057): No fullscreen media element found.
[task 2021-12-04T01:43:06.370Z] 01:43:06     INFO -  12-04 01:42:35.490 D/GeckoViewMediaControl( 3454): receiveMessage: name=GeckoView:MediaControl:Fullscreen, data={"metadata":{},"enabled":true}
[task 2021-12-04T01:43:06.370Z] 01:43:06     INFO -  12-04 01:42:35.490 D/GeckoViewMediaControl( 3454): handleFullscreenChanged true
[task 2021-12-04T01:43:06.370Z] 01:43:06     INFO -  12-04 01:42:35.540 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"9387e95a-6366-4f4b-a552-671ce7bd52b1","eval":"this['28102f26-6eb3-4738-8350-630df5e558b9'] = screen.orientation.lock('portrait-primary'); true"}}
[task 2021-12-04T01:43:06.370Z] 01:43:06     INFO -  12-04 01:42:35.591 D/GeckoScreenOrientation( 3454): updating to new orientation PORTRAIT_PRIMARY
[task 2021-12-04T01:43:06.370Z] 01:43:06     INFO -  12-04 01:42:35.642 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"da0c462f-3036-44a3-a782-4199a8f179c6","eval":"this['28102f26-6eb3-4738-8350-630df5e558b9']"}}
[task 2021-12-04T01:43:06.370Z] 01:43:06     INFO -  12-04 01:42:36.392 D/GeckoSession( 3454): handleMessage GeckoView:StateUpdated uri=null
[task 2021-12-04T01:43:06.370Z] 01:43:06     INFO -  12-04 01:42:36.392 W/GeckoSession( 3454): No history entries found.
[task 2021-12-04T01:43:06.371Z] 01:43:06     INFO -  12-04 01:42:37.217 I/art     ( 1661): Starting a blocking GC Explicit
[task 2021-12-04T01:43:06.371Z] 01:43:06     INFO -  12-04 01:42:37.232 I/art     ( 1661): Explicit concurrent mark sweep GC freed 6412(479KB) AllocSpace objects, 3(60KB) LOS objects, 29% free, 9MB/13MB, paused 303us total 14.511ms
[task 2021-12-04T01:43:06.371Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): Error
[task 2021-12-04T01:43:06.371Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-12-04T01:43:06.371Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2021-12-04T01:43:06.371Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-04T01:43:06.371Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-04T01:43:06.371Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2021-12-04T01:43:06.372Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2183)
[task 2021-12-04T01:43:06.372Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2143)
[task 2021-12-04T01:43:06.372Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$ExtensionPromise.getValue(GeckoSessionTestRule.java:2110)
[task 2021-12-04T01:43:06.372Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.mozilla.geckoview.test.OrientationDelegateTest.orientationLockedAlready(OrientationDelegateTest.kt:57)
[task 2021-12-04T01:43:06.372Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-04T01:43:06.372Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-12-04T01:43:06.373Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-12-04T01:43:06.373Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-12-04T01:43:06.373Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-12-04T01:43:06.373Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1451)
[task 2021-12-04T01:43:06.373Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$TNUWVrkQlCzXHIjIbcLih1Q8TRE.run(lambda)
[task 2021-12-04T01:43:06.373Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-12-04T01:43:06.374Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-04T01:43:06.374Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-04T01:43:06.374Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at android.os.Looper.loop(Looper.java:154)
[task 2021-12-04T01:43:06.374Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-12-04T01:43:06.374Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-04T01:43:06.374Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-12-04T01:43:06.374Z] 01:43:06     INFO -  12-04 01:43:05.594 E/GeckoSessionTestRule( 3454): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-12-04T01:43:06.374Z] 01:43:06     INFO -  12-04 01:43:05.595 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"6cdd18dd-6808-4bca-be22-a445c6a51561","args":{"oldPrefs":{"dom.screenorientation.allow-lock":false,"full-screen-api.allow-trusted-requests-only":true}},"type":"RestorePrefs"}}
[task 2021-12-04T01:43:06.375Z] 01:43:06     INFO -  12-04 01:43:05.599 D/GeckoViewContent( 3454): handleEvent: DOMWindowClose
[task 2021-12-04T01:43:06.375Z] 01:43:06     INFO -  12-04 01:43:05.600 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:List null
[task 2021-12-04T01:43:06.375Z] 01:43:06     INFO -  12-04 01:43:05.601 E/GeckoSessionTestRule( 3454): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 orientationLockedAlready(org.mozilla.geckoview.test.OrientationDelegateTest)
[task 2021-12-04T01:43:06.375Z] 01:43:06  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.OrientationDelegateTest#orientationLockedAlready | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-12-04T01:43:06.375Z] 01:43:06     INFO -  TEST-INFO took 30678ms
[task 2021-12-04T01:43:06.644Z] 01:43:06     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=822
[task 2021-12-04T01:43:06.644Z] 01:43:06     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-12-04T01:43:06.644Z] 01:43:06     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-12-04T01:43:06.644Z] 01:43:06     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=orientationLockNoFullscreen
[task 2021-12-04T01:43:06.644Z] 01:43:06     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.OrientationDelegateTest
[task 2021-12-04T01:43:06.644Z] 01:43:06     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=404
[task 2021-12-04T01:43:06.644Z] 01:43:06     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1

Comment 1

[Intermittent Failures Robot]

4 failures in 3170 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1744372&startday=2021-11-29&endday=2021-12-05&tree=all

Comment 2

[[ex-Mozilla] Agi Sferro | :agi]

Cathy, could you take a look at this? It looks like this test is failing fairly often in CI.

Comment 3

[Cathy Lu [:calu]]

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #2)

Cathy, could you take a look at this? It looks like this test is failing fairly often in CI.

OH yes, thanks for the reminder. I initially looked at this, but wasn't sure how to reproduce the problem since the test is passing for me locally. Should I look at the specific platform android-em-7-0-x86_64-lite-qr? The test is just generically timing out.

Comment 4

[Intermittent Failures Robot]

22 failures in 660 pushes (0.033 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 19
• try: 3

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 17
  • debug: 6
  • debug-isolated-process: 5
  • opt: 6
• android-em-7-0-x86_64-lite-qr: 1
  • opt: 1
• android-em-7-0-x86_64-shippable-qr: 3
  • opt: 3
• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1

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

Comment 5

[[ex-Mozilla] Agi Sferro | :agi]

From the reports https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2021-12-01&endday=2021-12-08&tree=trunk&bug=1744372 it looks like this is happening pretty much anywhere, so I wouldn't think it's related to the platform.

Have you tried running ./mach geckoview-junit org.mozilla.geckoview.test.OrientationDelegateTest --run-until-failure ? that's usually a good way to reproduce intermittents like this one.

From the stacktrace:

org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
        at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
        at android.os.Handler.handleCallback(Handler.java:751)
        at android.os.Handler.dispatchMessage(Handler.java:95)
        at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
        at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2183)
        at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2143)
        at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$ExtensionPromise.getValue(GeckoSessionTestRule.java:2110)
        at org.mozilla.geckoview.test.OrientationDelegateTest.orientationLockedAlready(OrientationDelegateTest.kt:57)
        at java.lang.reflect.Method.invoke(Native Method)

it looks like the test is timing out here: https://searchfox.org/mozilla-central/rev/1674b86019a96f076e0f98f1d0f5f3ab9d4e9020/mobile/android/geckoview/src/androidTest/java/org/mozilla/geckoview/test/OrientationDelegateTest.kt#57 so maybe the promise is not resolving in this case? There could be a JavaScript error somewhere in the logs too.

Comment 6

[[ex-Mozilla] Agi Sferro | :agi]

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #5)

Have you tried running ./mach geckoview-junit org.mozilla.geckoview.test.OrientationDelegateTest --run-until-failure ? that's usually a good way to reproduce intermittents like this one.

Just tried here and I can reproduce after a few tries, so hopefully you can too.

Comment 7

[Intermittent Failures Robot]

36 failures in 731 pushes (0.049 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 34
• try: 1
• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 25
  • debug-isolated-process: 9
  • debug: 5
  • opt: 11
• android-em-7-0-x86_64-lite-qr: 6
  • opt: 5
  • debug: 1
• android-em-7-0-x86_64-shippable-qr: 4
  • opt: 4
• android-em-7-0-x86_64-shippable-lite-qr: 1
  • opt: 1

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

Comment 8

[Intermittent Failures Robot]

36 failures in 596 pushes (0.06 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 31
• mozilla-central: 4
• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 7
  • debug: 3
  • opt: 4
• android-em-7-0-x86_64-qr: 24
  • opt: 7
  • debug-isolated-process: 13
  • debug: 4
• android-em-7-0-x86_64-shippable-lite-qr: 2
  • opt: 2
• android-em-7-0-x86_64-shippable-qr: 3
  • opt: 3

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

Comment 9

[Intermittent Failures Robot]

40 failures in 581 pushes (0.069 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 34
• mozilla-central: 5
• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-shippable-lite-qr: 8
  • opt: 8
• android-em-7-0-x86_64-shippable-qr: 3
  • opt: 3
• android-em-7-0-x86_64-lite-qr: 7
  • debug: 3
  • opt: 4
• android-em-7-0-x86_64-qr: 22
  • debug: 8
  • debug-isolated-process: 7
  • opt: 7

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

Comment 10

[Intermittent Failures Robot]

16 failures in 125 pushes (0.128 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-central: 2

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 11
  • opt: 4
  • debug-isolated-process: 4
  • debug: 3
• android-em-7-0-x86_64-lite-qr: 3
  • opt: 2
  • debug: 1
• android-em-7-0-x86_64-shippable-qr: 2
  • opt: 2

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

Comment 11

[Iulian Moraru]

Update:
There have been 160 failures within the last 7 days:
• 8 failures on Android 7.0 x86-64 Lite WebRender debug
• 17 failures on Android 7.0 x86-64 Lite WebRender opt
• 27 failures on Android 7.0 x86-64 WebRender debug
• 43 failures on Android 7.0 x86-64 WebRender debug-isolated-process
• 39 failures on Android 7.0 x86-64 WebRender opt
• 12 failures on Android 7.0 x86-64 Lite WebRender Shippable opt
• 14 failures on Android 7.0 x86-64 Shippable WebRender opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=360937536&repo=autoland&lineNumber=8632

[task 2021-12-12T04:35:03.623Z] 04:35:03     INFO -  TEST-START | org.mozilla.geckoview.test.OrientationDelegateTest#orientationLockedAlready
[task 2021-12-12T04:35:34.258Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=824
[task 2021-12-12T04:35:34.258Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-12-12T04:35:34.259Z] 04:35:34     INFO -  org.mozilla.geckoview.test | Error in orientationLockedAlready(org.mozilla.geckoview.test.OrientationDelegateTest):
[task 2021-12-12T04:35:34.259Z] 04:35:34     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2183)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2143)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$ExtensionPromise.getValue(GeckoSessionTestRule.java:2110)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.OrientationDelegateTest.orientationLockedAlready(OrientationDelegateTest.kt:57)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-12-12T04:35:34.261Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1451)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$TNUWVrkQlCzXHIjIbcLih1Q8TRE.run(lambda)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:154)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-12T04:35:34.262Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test |
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=orientationLockedAlready
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.OrientationDelegateTest
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-12T04:35:34.263Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-12T04:35:34.264Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2021-12-12T04:35:34.264Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2183)
[task 2021-12-12T04:35:34.264Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2143)
[task 2021-12-12T04:35:34.264Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$ExtensionPromise.getValue(GeckoSessionTestRule.java:2110)
[task 2021-12-12T04:35:34.264Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.OrientationDelegateTest.orientationLockedAlready(OrientationDelegateTest.kt:57)
[task 2021-12-12T04:35:34.265Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-12T04:35:34.265Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-12-12T04:35:34.265Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-12-12T04:35:34.266Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-12-12T04:35:34.266Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-12-12T04:35:34.267Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1451)
[task 2021-12-12T04:35:34.267Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$TNUWVrkQlCzXHIjIbcLih1Q8TRE.run(lambda)
[task 2021-12-12T04:35:34.267Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-12-12T04:35:34.268Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-12T04:35:34.268Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-12T04:35:34.268Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:154)
[task 2021-12-12T04:35:34.268Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-12-12T04:35:34.269Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-12T04:35:34.269Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-12-12T04:35:34.269Z] 04:35:34     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-12-12T04:35:34.269Z] 04:35:34     INFO -  org.mozilla.geckoview.test |
[task 2021-12-12T04:35:34.270Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=405
[task 2021-12-12T04:35:34.270Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2021-12-12T04:35:34.270Z] 04:35:34     INFO -  Printing logcat for test:
[task 2021-12-12T04:35:34.339Z] 04:35:34     INFO -  12-12 04:35:03.776 E/GeckoSessionTestRule( 3476): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec orientationLockedAlready(org.mozilla.geckoview.test.OrientationDelegateTest)
[task 2021-12-12T04:35:34.340Z] 04:35:34     INFO -  12-12 04:35:03.776 E/GeckoSessionTestRule( 3476): before prepareStatement orientationLockedAlready(org.mozilla.geckoview.test.OrientationDelegateTest)
[task 2021-12-12T04:35:34.340Z] 04:35:34     INFO -  12-12 04:35:03.778 I/Gecko   ( 3476): nsWindow[0x7c7285a27400]::Create 0x0 [0 0 1 1]
[task 2021-12-12T04:35:34.340Z] 04:35:34     INFO -  12-12 04:35:03.788 E/eglCodecCommon( 3476): glUtilsParamSize: unknow param 0x00008caa
[task 2021-12-12T04:35:34.341Z] 04:35:34     INFO -  12-12 04:35:03.813 W/webrender::device::gl( 3476): Missing optimized shader source for gpu_cache_update
[task 2021-12-12T04:35:34.341Z] 04:35:34     INFO -  12-12 04:35:03.821 E/eglCodecCommon( 3476): glUtilsParamSize: unknow param 0x00008741
[task 2021-12-12T04:35:34.341Z] 04:35:34     INFO -  12-12 04:35:03.836 I/Gecko   ( 3476): [Parent 3476, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4235
[task 2021-12-12T04:35:34.342Z] 04:35:34     INFO -  12-12 04:35:03.837 I/Gecko   ( 3476): [Parent 3476, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4235
[task 2021-12-12T04:35:34.342Z] 04:35:34     INFO -  12-12 04:35:03.860 D/GeckoViewNavigation( 3476): sessionContextId=null
[task 2021-12-12T04:35:34.343Z] 04:35:34     INFO -  12-12 04:35:03.868 D/GeckoViewModule( 3476): 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-12-12T04:35:34.343Z] 04:35:34     INFO -  12-12 04:35:03.870 D/GeckoViewNavigation( 3476): onInit
[task 2021-12-12T04:35:34.343Z] 04:35:34     INFO -  12-12 04:35:03.870 D/GeckoViewModule( 3476): registerListener ["GeckoView:GoBack","GeckoView:GoForward","GeckoView:GotoHistoryIndex","GeckoView:LoadUri","GeckoView:Reload","GeckoView:Stop","GeckoView:PurgeHistory"]
[task 2021-12-12T04:35:34.344Z] 04:35:34     INFO -  12-12 04:35:03.870 D/GeckoViewNavigation( 3476): onEnable
[task 2021-12-12T04:35:34.344Z] 04:35:34     INFO -  12-12 04:35:03.872 D/GeckoViewProcessHangMonitor( 3476): onInit
[task 2021-12-12T04:35:34.344Z] 04:35:34     INFO -  12-12 04:35:03.872 D/GeckoViewProcessHangMonitor( 3476): onEnable
[task 2021-12-12T04:35:34.344Z] 04:35:34     INFO -  12-12 04:35:03.872 D/GeckoViewModule( 3476): registerListener ["GeckoView:HangReportStop","GeckoView:HangReportWait"]
[task 2021-12-12T04:35:34.344Z] 04:35:34     INFO -  12-12 04:35:03.873 D/GeckoViewProgress( 3476): onEnable
[task 2021-12-12T04:35:34.345Z] 04:35:34     INFO -  12-12 04:35:03.874 D/GeckoSession( 3476): handleMessage GeckoView:PageStart uri=about:blank
[task 2021-12-12T04:35:34.345Z] 04:35:34     INFO -  12-12 04:35:03.874 E/GeckoSessionTestRule( 3476): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStart(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2021-12-12T04:35:34.346Z] 04:35:34     INFO -  12-12 04:35:03.874 D/GeckoSession( 3476): handleMessage GeckoView:LocationChange uri=about:blank
[task 2021-12-12T04:35:34.346Z] 04:35:34     INFO -  12-12 04:35:03.874 E/GeckoSessionTestRule( 3476): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String,java.util.List)
[task 2021-12-12T04:35:34.346Z] 04:35:34     INFO -  12-12 04:35:03.874 E/GeckoSessionTestRule( 3476): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2021-12-12T04:35:34.347Z] 04:35:34     INFO -  12-12 04:35:03.874 E/GeckoSessionTestRule( 3476): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoBack(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-12-12T04:35:34.347Z] 04:35:34     INFO -  12-12 04:35:03.874 E/GeckoSessionTestRule( 3476): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onCanGoForward(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-12-12T04:35:34.347Z] 04:35:34     INFO -  12-12 04:35:03.874 D/GeckoSession( 3476): handleMessage GeckoView:PageStop uri=null
[task 2021-12-12T04:35:34.347Z] 04:35:34     INFO -  12-12 04:35:03.874 E/GeckoSessionTestRule( 3476): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStop(org.mozilla.geckoview.GeckoSession,boolean)
[task 2021-12-12T04:35:34.348Z] 04:35:34     INFO -  12-12 04:35:03.874 E/GeckoSessionTestRule( 3476): after prepareStatement
[task 2021-12-12T04:35:34.348Z] 04:35:34     INFO -  12-12 04:35:03.875 D/GeckoViewModule( 3476): registerListener GeckoView:FlushSessionState
[task 2021-12-12T04:35:34.348Z] 04:35:34     INFO -  12-12 04:35:03.876 D/GeckoViewSettings( 3476): onInit
[task 2021-12-12T04:35:34.348Z] 04:35:34     INFO -  12-12 04:35:03.876 D/GeckoViewModule( 3476): registerListener ["GeckoView:GetUserAgent"]
[task 2021-12-12T04:35:34.349Z] 04:35:34     INFO -  12-12 04:35:03.877 D/GeckoViewSettings( 3476): 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-12-12T04:35:34.349Z] 04:35:34     INFO -  12-12 04:35:03.878 D/GeckoViewModule( 3476): registerListener ["GeckoView:WebExtension:SetTabActive"]
[task 2021-12-12T04:35:34.349Z] 04:35:34     INFO -  12-12 04:35:03.879 D/GeckoViewModule( 3476): registerListener ["ContentBlocking:RequestLog"]
[task 2021-12-12T04:35:34.349Z] 04:35:34     INFO -  12-12 04:35:03.880 D/GeckoViewMediaControl( 3476): onEnable
[task 2021-12-12T04:35:34.350Z] 04:35:34     INFO -  12-12 04:35:03.880 D/GeckoViewModule( 3476): 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-12-12T04:35:34.350Z] 04:35:34     INFO -  12-12 04:35:03.882 I/Gecko   ( 3476): AndroidBridge::GetScreenOrientation
[task 2021-12-12T04:35:34.350Z] 04:35:34     INFO -  12-12 04:35:03.884 D/GeckoViewSelectionActionDelegate[C]( 7290): handleEvent: visibilitychange
[task 2021-12-12T04:35:34.350Z] 04:35:34     INFO -  12-12 04:35:03.884 I/GeckoSession( 3476): zerdatime 303668 - chrome startup finished
[task 2021-12-12T04:35:34.350Z] 04:35:34     INFO -  12-12 04:35:03.885 I/Gecko   ( 3476): nsWindow[0x7c7285a27400]::Show 1
[task 2021-12-12T04:35:34.350Z] 04:35:34     INFO -  12-12 04:35:03.887 D/GeckoViewConsole( 3476): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"4d97b4f1-8f5b-4c86-8907-0553e2b96d2c","args":{"oldPrefs":{},"newPrefs":{"dom.screenorientation.allow-lock":true}},"type":"SetPrefs"}}
[task 2021-12-12T04:35:34.351Z] 04:35:34     INFO -  12-12 04:35:03.888 D/GeckoViewSettings[C]( 7290): receiveMessage: SettingsUpdate
[task 2021-12-12T04:35:34.351Z] 04:35:34     INFO -  12-12 04:35:03.889 W/GeckoEditableChild( 7290): No editable parent
[task 2021-12-12T04:35:34.351Z] 04:35:34     INFO -  12-12 04:35:03.892 D/GeckoViewXUL( 3476): receiveMessage GeckoView:ContentModuleLoaded {"module":"SessionStateAggregator"}
[task 2021-12-12T04:35:34.351Z] 04:35:34     INFO -  12-12 04:35:03.893 D/GeckoViewConsole( 3476): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"46709685-7dc0-4af8-8b18-a09540ba3e15","args":{"oldPrefs":{"dom.screenorientation.allow-lock":false},"newPrefs":{"full-screen-api.allow-trusted-requests-only":false}},"type":"SetPrefs"}}
[task 2021-12-12T04:35:34.351Z] 04:35:34     INFO -  12-12 04:35:03.897 D/GeckoViewModule( 3476): dispatch GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/fullscreen.html","flags":0,"headerFilter":1}
[task 2021-12-12T04:35:34.352Z] 04:35:34     INFO -  12-12 04:35:03.897 D/GeckoViewNavigation( 3476): onEvent: event=GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/fullscreen.html","flags":0,"headerFilter":1}
[task 2021-12-12T04:35:34.352Z] 04:35:34     INFO -  12-12 04:35:03.907 D/GeckoViewProgress( 3476): ProgressTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK
[task 2021-12-12T04:35:34.352Z] 04:35:34     INFO -  12-12 04:35:03.907 D/GeckoViewProgress( 3476): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-12T04:35:34.352Z] 04:35:34     INFO -  12-12 04:35:03.908 D/GeckoViewProgress( 3476): ProgressTracker start http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-12T04:35:34.353Z] 04:35:34     INFO -  12-12 04:35:03.908 D/GeckoViewProgress( 3476): ProgressTracker updateProgress
[task 2021-12-12T04:35:34.353Z] 04:35:34     INFO -  12-12 04:35:03.908 D/GeckoViewProgress( 3476): ProgressTracker updateProgress data={"prev":0,"uri":"http://localhost:4245/assets/www/fullscreen.html","locationChange":false,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":false} progress=15
[task 2021-12-12T04:35:34.353Z] 04:35:34     INFO -  12-12 04:35:03.909 D/GeckoSession( 3476): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-12-12T04:35:34.353Z] 04:35:34     INFO -  12-12 04:35:03.910 D/GeckoViewProgress( 3476): StateTracker onStateChange: isTopLevel=true, flags=0xf0001, status=NS_OK loadType=1
[task 2021-12-12T04:35:34.354Z] 04:35:34     INFO -  12-12 04:35:03.910 D/GeckoSession( 3476): handleMessage GeckoView:PageStart uri=http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-12T04:35:34.354Z] 04:35:34     INFO -  12-12 04:35:03.925 D/GeckoViewSelectionActionDelegate[C]( 7290): handleEvent: visibilitychange
[task 2021-12-12T04:35:34.354Z] 04:35:34     INFO -  12-12 04:35:03.927 D/GeckoViewAutoFill[C]( 7290): handleEvent: pagehide
[task 2021-12-12T04:35:34.354Z] 04:35:34     INFO -  12-12 04:35:03.928 D/GeckoViewAutofill( 7290): Clearing auto-fill
[task 2021-12-12T04:35:34.354Z] 04:35:34     INFO -  12-12 04:35:03.948 D/GeckoViewNavigation( 3476): onLocationChange
[task 2021-12-12T04:35:34.354Z] 04:35:34     INFO -  12-12 04:35:03.949 W/Web Content( 7290): [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/fullscreen.html" line: 0}]
[task 2021-12-12T04:35:34.355Z] 04:35:34     INFO -  12-12 04:35:03.952 D/GeckoSession( 3476): handleMessage GeckoView:LocationChange uri=http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-12T04:35:34.355Z] 04:35:34     INFO -  12-12 04:35:03.952 D/GeckoViewProgress( 3476): SecurityTracker onLocationChange: location=http://localhost:4245/assets/www/fullscreen.html, flags=0
[task 2021-12-12T04:35:34.355Z] 04:35:34     INFO -  12-12 04:35:03.952 D/GeckoViewProgress( 3476): ProgressTracker onLocationChange: location=http://localhost:4245/assets/www/fullscreen.html, flags=0
[task 2021-12-12T04:35:34.355Z] 04:35:34     INFO -  12-12 04:35:03.952 D/GeckoViewProgress( 3476): ProgressTracker changeLocation http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-12T04:35:34.355Z] 04:35:34     INFO -  12-12 04:35:03.953 D/GeckoViewProgress( 3476): onSecurityChange
[task 2021-12-12T04:35:34.356Z] 04:35:34     INFO -  12-12 04:35:03.953 D/GeckoSession( 3476): handleMessage GeckoView:SecurityChanged uri=null
[task 2021-12-12T04:35:34.356Z] 04:35:34     INFO -  12-12 04:35:03.966 D/GeckoViewContent( 3476): handleEvent: pagetitlechanged
[task 2021-12-12T04:35:34.356Z] 04:35:34     INFO -  12-12 04:35:03.967 D/GeckoViewContentDelegateChild[C]( 7290): handleEvent: DOMContentLoaded
[task 2021-12-12T04:35:34.356Z] 04:35:34     INFO -  12-12 04:35:03.968 D/GeckoViewProgressDelegate[C]( 7290): handleEvent: DOMContentLoaded
[task 2021-12-12T04:35:34.356Z] 04:35:34     INFO -  12-12 04:35:03.969 D/GeckoViewProgress( 3476): receiveMessage: DOMContentLoaded
[task 2021-12-12T04:35:34.356Z] 04:35:34     INFO -  12-12 04:35:03.970 D/GeckoViewProgress( 3476): ProgressTracker handleEvent: DOMContentLoaded
[task 2021-12-12T04:35:34.356Z] 04:35:34     INFO -  12-12 04:35:03.970 D/GeckoViewProgress( 3476): ProgressTracker updateProgress
[task 2021-12-12T04:35:34.357Z] 04:35:34     INFO -  12-12 04:35:03.970 D/GeckoViewProgress( 3476): ProgressTracker updateProgress data={"prev":15,"uri":"http://localhost:4245/assets/www/fullscreen.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":false,"parsed":true} progress=55
[task 2021-12-12T04:35:34.357Z] 04:35:34     INFO -  12-12 04:35:03.970 D/GeckoSession( 3476): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-12-12T04:35:34.357Z] 04:35:34     INFO -  12-12 04:35:03.993 D/GeckoViewProgressDelegate[C]( 7290): handleEvent: pageshow
[task 2021-12-12T04:35:34.357Z] 04:35:34     INFO -  12-12 04:35:03.995 D/GeckoViewAutoFill[C]( 7290): handleEvent: pageshow
[task 2021-12-12T04:35:34.358Z] 04:35:34     INFO -  12-12 04:35:03.996 D/GeckoViewContent[C]( 7290): handleEvent: pageshow
[task 2021-12-12T04:35:34.358Z] 04:35:34     INFO -  12-12 04:35:03.998 D/WebExtension( 3476): handleMessage GeckoView:WebExtension:Connect
[task 2021-12-12T04:35:34.358Z] 04:35:34     INFO -  12-12 04:35:04.000 D/GeckoViewProgress( 3476): receiveMessage: pageshow
[task 2021-12-12T04:35:34.358Z] 04:35:34     INFO -  12-12 04:35:04.000 D/GeckoViewProgress( 3476): ProgressTracker handleEvent: pageshow
[task 2021-12-12T04:35:34.358Z] 04:35:34     INFO -  12-12 04:35:04.000 D/GeckoViewProgress( 3476): ProgressTracker updateProgress
[task 2021-12-12T04:35:34.359Z] 04:35:34     INFO -  12-12 04:35:04.001 D/GeckoViewProgress( 3476): ProgressTracker updateProgress data={"prev":55,"uri":"http://localhost:4245/assets/www/fullscreen.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":true,"parsed":true} progress=100
[task 2021-12-12T04:35:34.359Z] 04:35:34     INFO -  12-12 04:35:04.001 D/GeckoSession( 3476): handleMessage GeckoView:ProgressChanged uri=null
[task 2021-12-12T04:35:34.359Z] 04:35:34     INFO -  12-12 04:35:04.005 D/GeckoViewProgress( 3476): ProgressTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK
[task 2021-12-12T04:35:34.359Z] 04:35:34     INFO -  12-12 04:35:04.005 D/GeckoViewProgress( 3476): ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/fullscreen.html
[task 2021-12-12T04:35:34.359Z] 04:35:34     INFO -  12-12 04:35:04.005 D/GeckoViewProgress( 3476): ProgressTracker stop
[task 2021-12-12T04:35:34.359Z] 04:35:34     INFO -  12-12 04:35:04.005 D/GeckoViewProgress( 3476): ProgressTracker updateProgress
[task 2021-12-12T04:35:34.359Z] 04:35:34     INFO -  12-12 04:35:04.006 D/GeckoViewProgress( 3476): StateTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK loadType=1
[task 2021-12-12T04:35:34.360Z] 04:35:34     INFO -  12-12 04:35:04.007 D/GeckoSession( 3476): handleMessage GeckoView:PageStop uri=null
[task 2021-12-12T04:35:34.360Z] 04:35:34     INFO -  12-12 04:35:04.007 D/GeckoViewConsole( 3476): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"afd9f3d3-0db5-4981-ab0d-8bacfe72051b","eval":"this['7785b95f-1c80-4b32-8047-5e89ddcee670'] = document.querySelector('#fullscreen').requestFullscreen(); true"}}
[task 2021-12-12T04:35:34.360Z] 04:35:34     INFO -  12-12 04:35:04.013 D/GeckoViewContentDelegateChild[C]( 7290): handleEvent: MozDOMFullscreen:Request
[task 2021-12-12T04:35:34.360Z] 04:35:34     INFO -  12-12 04:35:04.014 D/GeckoViewContentDelegateParent( 3476): receiveMessage: GeckoView:DOMFullscreenRequest {"data":{},"json":{},"name":"GeckoView:DOMFullscreenRequest","sync":false,"target":{}}
[task 2021-12-12T04:35:34.360Z] 04:35:34     INFO -  12-12 04:35:04.018 D/GeckoViewConsole( 3476): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"d602c4e8-deb5-4c9d-a579-44957538b9a0","eval":"this['7785b95f-1c80-4b32-8047-5e89ddcee670']"}}
[task 2021-12-12T04:35:34.361Z] 04:35:34     INFO -  12-12 04:35:04.096 D/GeckoViewContent( 3476): handleEvent: MozDOMFullscreen:Entered
[task 2021-12-12T04:35:34.361Z] 04:35:34     INFO -  12-12 04:35:04.099 D/GeckoViewContent[C]( 7290): receiveMessage: GeckoView:DOMFullscreenEntered
[task 2021-12-12T04:35:34.361Z] 04:35:34     INFO -  12-12 04:35:04.102 D/GeckoViewContentDelegateChild[C]( 7290): handleEvent: MozDOMFullscreen:Entered
[task 2021-12-12T04:35:34.361Z] 04:35:34     INFO -  12-12 04:35:04.104 D/GeckoViewMediaControlDelegateChild[C]( 7290): handleEvent: MozDOMFullscreen:Entered
[task 2021-12-12T04:35:34.361Z] 04:35:34     INFO -  12-12 04:35:04.104 I/Gecko   ( 3476): nsWindow 0x7c7284be2100 destructor
[task 2021-12-12T04:35:34.361Z] 04:35:34     INFO -  12-12 04:35:04.104 I/Gecko   ( 3476): nsWindow 0x7c728233f700 destructor
[task 2021-12-12T04:35:34.361Z] 04:35:34     INFO -  12-12 04:35:04.104 D/GeckoViewMediaControlDelegateChild[C]( 7290): handleFullscreenChanged
[task 2021-12-12T04:35:34.361Z] 04:35:34     INFO -  12-12 04:35:04.105 D/GeckoViewMediaControlDelegateChild[C]( 7290): No fullscreen media element found.
[task 2021-12-12T04:35:34.362Z] 04:35:34     INFO -  12-12 04:35:04.117 D/GeckoViewConsole( 3476): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"ba62979e-d074-4194-9e64-3b084fa2f21e","eval":"this['0e7ed8d7-85b7-458b-9a2f-bd551b183df2'] = screen.orientation.lock('portrait-primary'); true"}}
[task 2021-12-12T04:35:34.362Z] 04:35:34     INFO -  12-12 04:35:04.120 D/GeckoScreenOrientation( 3476): updating to new orientation PORTRAIT_PRIMARY
[task 2021-12-12T04:35:34.362Z] 04:35:34     INFO -  12-12 04:35:04.125 D/GeckoViewConsole( 3476): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"47cabed7-7133-4d25-8028-f662a4b595ff","eval":"this['0e7ed8d7-85b7-458b-9a2f-bd551b183df2']"}}
[task 2021-12-12T04:35:34.362Z] 04:35:34     INFO -  12-12 04:35:04.972 W/GeckoSession( 3476): No history entries found.
[task 2021-12-12T04:35:34.362Z] 04:35:34     INFO -  12-12 04:35:04.972 D/GeckoSession( 3476): handleMessage GeckoView:StateUpdated uri=null
[task 2021-12-12T04:35:34.362Z] 04:35:34     INFO -  12-12 04:35:05.776 I/art     ( 1655): Starting a blocking GC Explicit
[task 2021-12-12T04:35:34.362Z] 04:35:34     INFO -  12-12 04:35:05.792 I/art     ( 1655): Explicit concurrent mark sweep GC freed 8165(679KB) AllocSpace objects, 4(100KB) LOS objects, 29% free, 9MB/13MB, paused 222us total 16.323ms
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:09.827 I/Gecko   ( 3476): nsWindow 0x7c728230fa00 destructor
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:09.827 I/Gecko   ( 3476): nsWindow 0x7c728b522400 destructor
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:09.827 I/Gecko   ( 3476): nsWindow 0x7c7285a29200 destructor
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:09.827 I/Gecko   ( 3476): nsWindow 0x7c7288558900 destructor
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:09.827 I/Gecko   ( 3476): nsWindow 0x7c7282311200 destructor
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:09.827 I/Gecko   ( 3476): nsWindow 0x7c7284b3a100 destructor
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:09.914 I/Gecko   ( 3476): nsWindow 0x7c7284be0f00 destructor
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:31.994 I/Gecko   ( 3476): [Parent 3476, Main Thread] WARNING: 'mProgress != Progress::ShutdownCompleted', file /builds/worker/checkouts/gecko/dom/serviceworkers/ServiceWorkerShutdownState.cpp:57
[task 2021-12-12T04:35:34.363Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): Error
[task 2021-12-12T04:35:34.364Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-12-12T04:35:34.364Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2021-12-12T04:35:34.364Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-12T04:35:34.364Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-12T04:35:34.364Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2021-12-12T04:35:34.364Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2183)
[task 2021-12-12T04:35:34.365Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2143)
[task 2021-12-12T04:35:34.365Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$ExtensionPromise.getValue(GeckoSessionTestRule.java:2110)
[task 2021-12-12T04:35:34.365Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.mozilla.geckoview.test.OrientationDelegateTest.orientationLockedAlready(OrientationDelegateTest.kt:57)
[task 2021-12-12T04:35:34.365Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-12T04:35:34.365Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-12-12T04:35:34.365Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-12-12T04:35:34.365Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-12-12T04:35:34.365Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-12-12T04:35:34.366Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1451)
[task 2021-12-12T04:35:34.366Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$TNUWVrkQlCzXHIjIbcLih1Q8TRE.run(lambda)
[task 2021-12-12T04:35:34.366Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-12-12T04:35:34.366Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-12-12T04:35:34.366Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-12-12T04:35:34.366Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at android.os.Looper.loop(Looper.java:154)
[task 2021-12-12T04:35:34.366Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-12-12T04:35:34.366Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-12-12T04:35:34.367Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-12-12T04:35:34.367Z] 04:35:34     INFO -  12-12 04:35:34.125 E/GeckoSessionTestRule( 3476): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-12-12T04:35:34.367Z] 04:35:34     INFO -  12-12 04:35:34.129 D/GeckoViewConsole( 3476): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"03010202-48a1-4f3a-bbc2-4a2906e6c759","args":{"oldPrefs":{"dom.screenorientation.allow-lock":false,"full-screen-api.allow-trusted-requests-only":true}},"type":"RestorePrefs"}}
[task 2021-12-12T04:35:34.367Z] 04:35:34     INFO -  12-12 04:35:34.145 D/GeckoViewContent( 3476): handleEvent: DOMWindowClose
[task 2021-12-12T04:35:34.367Z] 04:35:34     INFO -  12-12 04:35:34.147 D/GeckoViewConsole( 3476): onEvent GeckoView:WebExtension:List null
[task 2021-12-12T04:35:34.367Z] 04:35:34     INFO -  12-12 04:35:34.152 I/Gecko   ( 3476): nsWindow[0x7c7285a27400]::Show 0
[task 2021-12-12T04:35:34.368Z] 04:35:34     INFO -  12-12 04:35:34.152 E/GeckoSessionTestRule( 3476): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 orientationLockedAlready(org.mozilla.geckoview.test.OrientationDelegateTest)
[task 2021-12-12T04:35:34.368Z] 04:35:34  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.OrientationDelegateTest#orientationLockedAlready | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2021-12-12T04:35:34.368Z] 04:35:34     INFO -  TEST-INFO took 30718ms
[task 2021-12-12T04:35:34.608Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=824
[task 2021-12-12T04:35:34.609Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-12-12T04:35:34.609Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-12-12T04:35:34.609Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=orientationLockNoFullscreen
[task 2021-12-12T04:35:34.610Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.OrientationDelegateTest
[task 2021-12-12T04:35:34.610Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=406
[task 2021-12-12T04:35:34.610Z] 04:35:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2021-12-12T04:35:34.610Z] 04:35:34     INFO -  TEST-START | org.mozilla.geckoview.test.OrientationDelegateTest#orientationLockNoFullscreen

Comment 12

[Intermittent Failures Robot]

172 failures in 3319 pushes (0.052 failures/push) were associated with this bug in the last 7 days.

This is the #2 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 151
• mozilla-central: 14
• try: 7

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 112
  • opt: 41
  • debug-isolated-process: 44
  • debug: 27
• android-em-7-0-x86_64-lite-qr: 26
  • opt: 18
  • debug: 8
• android-em-7-0-x86_64-shippable-qr: 18
  • opt: 18
• android-em-7-0-x86_64-shippable-lite-qr: 16
  • opt: 16

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

Comment 13

[Cathy Lu [:calu]]

Attachment: Bug 1744372 Temporarily disable OrientationLockedAlready test until further investigation

Comment 14

[Intermittent Failures Robot]

35 failures in 529 pushes (0.066 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 29
• mozilla-central: 5
• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 11
  • opt: 4
  • debug: 7
• android-em-7-0-x86_64-qr: 20
  • debug: 4
  • opt: 4
  • debug-isolated-process: 12
• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1
• android-em-7-0-x86_64-shippable-lite-qr: 3
  • opt: 3

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

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fa1e33c47711
Temporarily disable OrientationLockedAlready test until further investigation r=geckoview-reviewers,agi DONTBUILD

Comment 16

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/fa1e33c47711

Comment 17

[Intermittent Failures Robot]

20 failures in 494 pushes (0.04 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 16
• mozilla-central: 4

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 12
  • opt: 10
  • debug-isolated-process: 1
  • debug: 1
• android-em-7-0-x86_64-shippable-lite-qr: 3
  • opt: 3
• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1
• android-em-7-0-x86_64-lite-qr: 4
  • debug: 3
  • opt: 1

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

Comment 18

[Cathy Lu [:calu]]

Attachment: Bug 1744372 - Update ScreenOrientation junit tests to assert when called, Fix intermittent test

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2c242fa34cb6
Update ScreenOrientation junit tests to assert when called, Fix intermittent test r=geckoview-reviewers,agi

Comment 20

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/2c242fa34cb6

Comment 21

[Intermittent Failures Robot]

55 failures in 3263 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

This is the #18 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 45
• mozilla-central: 9
• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 15
  • opt: 5
  • debug: 10
• android-em-7-0-x86_64-qr: 32
  • debug: 5
  • opt: 14
  • debug-isolated-process: 13
• android-em-7-0-x86_64-shippable-qr: 2
  • opt: 2
• android-em-7-0-x86_64-shippable-lite-qr: 6
  • opt: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1744372&startday=2021-12-13&endday=2021-12-19&tree=all