Closed Bug 1768336 Opened 3 years ago Closed 3 years ago

Intermittent org.mozilla.geckoview.test.WebNotificationTest#onCloseNotification | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms

Categories

(GeckoView :: General, defect, P5)

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

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

[task 2022-05-07T17:12:20.381Z] 17:12:20     INFO -  TEST-START | org.mozilla.geckoview.test.WebNotificationTest#onCloseNotification
[task 2022-05-07T17:12:50.732Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=902
[task 2022-05-07T17:12:50.732Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2022-05-07T17:12:50.733Z] 17:12:50     INFO -  org.mozilla.geckoview.test | Error in onCloseNotification(org.mozilla.geckoview.test.WebNotificationTest):
[task 2022-05-07T17:12:50.733Z] 17:12:50     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-05-07T17:12:50.733Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-05-07T17:12:50.734Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-05-07T17:12:50.734Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-05-07T17:12:50.735Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-05-07T17:12:50.735Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2237)
[task 2022-05-07T17:12:50.735Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2197)
[task 2022-05-07T17:12:50.736Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForJS(GeckoSessionTestRule.java:2363)
[task 2022-05-07T17:12:50.736Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.waitForJS(BaseSessionTest.kt:221)
[task 2022-05-07T17:12:50.737Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.WebNotificationTest.setup(WebNotificationTest.kt:36)
[task 2022-05-07T17:12:50.737Z] 17:12:50     INFO -  org.mozilla.geckoview.test |
[task 2022-05-07T17:12:50.737Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2022-05-07T17:12:50.737Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=onCloseNotification
[task 2022-05-07T17:12:50.737Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.WebNotificationTest
[task 2022-05-07T17:12:50.738Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-05-07T17:12:50.738Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:49)
[task 2022-05-07T17:12:50.738Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-05-07T17:12:50.739Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-05-07T17:12:50.739Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:158)
[task 2022-05-07T17:12:50.739Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2237)
[task 2022-05-07T17:12:50.740Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2197)
[task 2022-05-07T17:12:50.740Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForJS(GeckoSessionTestRule.java:2363)
[task 2022-05-07T17:12:50.740Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.waitForJS(BaseSessionTest.kt:221)
[task 2022-05-07T17:12:50.741Z] 17:12:50     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.WebNotificationTest.setup(WebNotificationTest.kt:36)
[task 2022-05-07T17:12:50.741Z] 17:12:50     INFO -  org.mozilla.geckoview.test |
[task 2022-05-07T17:12:50.741Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=887
[task 2022-05-07T17:12:50.741Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2022-05-07T17:12:50.741Z] 17:12:50     INFO -  Printing logcat for test:
[task 2022-05-07T17:12:50.802Z] 17:12:50     INFO -  05-07 17:12:19.789 E/GeckoSessionTestRule( 3401): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec onCloseNotification(org.mozilla.geckoview.test.WebNotificationTest)
[task 2022-05-07T17:12:50.802Z] 17:12:50     INFO -  05-07 17:12:19.789 E/GeckoSessionTestRule( 3401): before prepareStatement onCloseNotification(org.mozilla.geckoview.test.WebNotificationTest)
[task 2022-05-07T17:12:50.803Z] 17:12:50     INFO -  05-07 17:12:19.789 E/eglCodecCommon(23734): glUtilsParamSize: unknow param 0x00008caa
[task 2022-05-07T17:12:50.803Z] 17:12:50     INFO -  05-07 17:12:19.791 D/GeckoViewStartup( 3401): onEvent GeckoView:StorageDelegate:Attached
[task 2022-05-07T17:12:50.804Z] 17:12:50     INFO -  05-07 17:12:19.794 E/GeckoSessionTestRule( 3401): method: public abstract void org.mozilla.geckoview.WebNotificationDelegate.onCloseNotification(org.mozilla.geckoview.WebNotification)
[task 2022-05-07T17:12:50.804Z] 17:12:50     INFO -  05-07 17:12:19.796 I/ServiceChildProcess( 2741): Destroying GeckoServiceChildProcess
[task 2022-05-07T17:12:50.804Z] 17:12:50     INFO -  05-07 17:12:19.796 I/art     ( 2741): System.exit called, status: 0
[task 2022-05-07T17:12:50.804Z] 17:12:50     INFO -  05-07 17:12:19.796 I/AndroidRuntime( 2741): VM exiting with result code 0, cleanup skipped.
[task 2022-05-07T17:12:50.805Z] 17:12:50     INFO -  05-07 17:12:19.803 D/GeckoViewNavigation( 3401): sessionContextId=null
[task 2022-05-07T17:12:50.805Z] 17:12:50     INFO -  05-07 17:12:19.808 E/eglCodecCommon(23734): glUtilsParamSize: unknow param 0x00008caa
[task 2022-05-07T17:12:50.805Z] 17:12:50     INFO -  05-07 17:12:19.816 E/eglCodecCommon(23734): glUtilsParamSize: unknow param 0x00008741
[task 2022-05-07T17:12:50.806Z] 17:12:50     INFO -  05-07 17:12:19.818 D/GeckoViewModule( 3401): registerListener ["GeckoViewContent:ExitFullScreen","GeckoView:ClearMatches","GeckoView:DisplayMatches","GeckoView:FindInPage","GeckoView:RestoreState","GeckoView:ScrollBy","GeckoView:ScrollTo","GeckoView:SetActive","GeckoView:SetFocused","GeckoView:UpdateInitData","GeckoView:ZoomToInput"]
[task 2022-05-07T17:12:50.807Z] 17:12:50     INFO -  05-07 17:12:19.818 D/GeckoViewNavigation( 3401): onInit
[task 2022-05-07T17:12:50.807Z] 17:12:50     INFO -  05-07 17:12:19.818 D/GeckoViewModule( 3401): registerListener ["GeckoView:GoBack","GeckoView:GoForward","GeckoView:GotoHistoryIndex","GeckoView:LoadUri","GeckoView:Reload","GeckoView:Stop","GeckoView:PurgeHistory"]
[task 2022-05-07T17:12:50.807Z] 17:12:50     INFO -  05-07 17:12:19.819 D/GeckoViewNavigation( 3401): onEnable
[task 2022-05-07T17:12:50.808Z] 17:12:50     INFO -  05-07 17:12:19.819 D/GeckoViewProcessHangMonitor( 3401): onInit
[task 2022-05-07T17:12:50.808Z] 17:12:50     INFO -  05-07 17:12:19.819 D/GeckoViewSelectionActionDelegate[C]( 2164): handleEvent: visibilitychange
[task 2022-05-07T17:12:50.808Z] 17:12:50     INFO -  05-07 17:12:19.819 D/GeckoViewProcessHangMonitor( 3401): onEnable
[task 2022-05-07T17:12:50.809Z] 17:12:50     INFO -  05-07 17:12:19.819 D/GeckoViewModule( 3401): registerListener ["GeckoView:HangReportStop","GeckoView:HangReportWait"]
[task 2022-05-07T17:12:50.809Z] 17:12:50     INFO -  05-07 17:12:19.819 D/GeckoViewProgress( 3401): onEnable
[task 2022-05-07T17:12:50.809Z] 17:12:50     INFO -  05-07 17:12:19.819 D/GeckoSession( 3401): handleMessage GeckoView:PageStart uri=about:blank
[task 2022-05-07T17:12:50.809Z] 17:12:50     INFO -  05-07 17:12:19.819 E/GeckoSessionTestRule( 3401): method: public abstract void org.mozilla.geckoview.GeckoSession$ProgressDelegate.onPageStart(org.mozilla.geckoview.GeckoSession,java.lang.String)
[task 2022-05-07T17:12:50.810Z] 17:12:50     INFO -  05-07 17:12:19.819 D/GeckoSession( 3401): handleMessage GeckoView:LocationChange uri=about:blank
[task 2022-05-07T17:12:50.810Z] 17:12:50     INFO -  05-07 17:12:19.819 E/GeckoSessionTestRule( 3401): method: public abstract void org.mozilla.geckoview.GeckoSession$NavigationDelegate.onLocationChange(org.mozilla.geckoview.GeckoSession,java.lang.String,java.util.List)
<...>
[task 2022-05-07T17:12:50.837Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2$$ExternalSyntheticLambda0.run(Unknown Source)
[task 2022-05-07T17:12:50.838Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
[task 2022-05-07T17:12:50.838Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
[task 2022-05-07T17:12:50.838Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2022-05-07T17:12:50.838Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2022-05-07T17:12:50.838Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2022-05-07T17:12:50.838Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at android.os.Looper.loop(Looper.java:154)
[task 2022-05-07T17:12:50.838Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2022-05-07T17:12:50.838Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2022-05-07T17:12:50.839Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2022-05-07T17:12:50.839Z] 17:12:50     INFO -  05-07 17:12:50.092 E/GeckoSessionTestRule( 3401): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2022-05-07T17:12:50.839Z] 17:12:50     INFO -  05-07 17:12:50.095 D/GeckoViewConsole( 3401): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"3cb2120d-2d58-4617-b889-98a116780bd2","args":{"oldPrefs":{"dom.webnotifications.requireuserinteraction":true}},"type":"RestorePrefs"}}
[task 2022-05-07T17:12:50.839Z] 17:12:50     INFO -  05-07 17:12:50.132 D/GeckoViewContent( 3401): handleEvent: DOMWindowClose
[task 2022-05-07T17:12:50.839Z] 17:12:50     INFO -  05-07 17:12:50.133 D/GeckoViewConsole( 3401): onEvent GeckoView:WebExtension:List null
[task 2022-05-07T17:12:50.839Z] 17:12:50     INFO -  05-07 17:12:50.134 E/GeckoSessionTestRule( 3401): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 onCloseNotification(org.mozilla.geckoview.test.WebNotificationTest)
[task 2022-05-07T17:12:50.840Z] 17:12:50  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.WebNotificationTest#onCloseNotification | org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  TEST-INFO took 30421ms
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=902
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=dismissNotification
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.WebNotificationTest
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=888
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2022-05-07T17:12:50.840Z] 17:12:50     INFO -  TEST-START | org.mozilla.geckoview.test.WebNotificationTest#dismissNotification

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

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

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

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

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

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