Closed Bug 1696785 Opened 3 years ago Closed 3 years ago

Intermittent org.mozilla.geckoview.test.SelectionActionDelegateTest#collapseToEnd[#textarea] | java.lang.AssertionError: Selection offsets should match

Categories

(GeckoView :: General, defect, P5)

Unspecified
All

Tracking

(firefox93 wontfix, firefox94 wontfix, firefox95 fixed)

RESOLVED FIXED
95 Branch
Tracking Status
firefox93 --- wontfix
firefox94 --- wontfix
firefox95 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: hiro)

References

Details

(Keywords: assertion, intermittent-failure)

Attachments

(1 file)

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


[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.358 D/GeckoViewConsole( 3142): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"988846a2-28f6-4f2e-a1b9-8528ac05df69","eval":"document.querySelector('#textarea').focus()"}}
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.363 D/GeckoViewAutofill[C]( 4254): handleEvent: focusin
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.365 D/GeckoViewConsole( 3142): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"3bbe9137-ad67-4f06-8a6c-a99f2bf7d957","args":{"oldPrefs":{},"newPrefs":{"geckoview.selection_action.show_on_focus":true,"layout.accessiblecaret.script_change_update_mode":2}},"type":"SetPrefs"}}
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.368 D/GeckoViewConsole( 3142): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"3b454797-f00d-4a58-b508-4cab07ef8b49","eval":"document.querySelector('#textarea').select()"}}
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.374 D/GeckoViewContentDelegateChild[C]( 4254): handleEvent: MozFirstContentfulPaint
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.375 D/GeckoViewContentDelegateChild[C]( 4254): handleEvent: MozFirstContentfulPaint
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.375 D/GeckoViewSelectionActionDelegate[C]( 4254): handleEvent: updateposition
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.377 D/GeckoViewContent[C]( 4254): handleEvent: mozcaretstatechanged
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.377 D/GeckoViewSelectionActionDelegate[C]( 4254): handleEvent: updateposition
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.379 D/GeckoViewConsole( 3142): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"17864619-1fdf-41ab-bb49-1aa0b2bb72a0","eval":"[ document.querySelector('#textarea').selectionStart,\ndocument.querySelector('#textarea').selectionEnd ]"}}
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.379 D/GeckoViewContent[C]( 4254): handleEvent: mozcaretstatechanged
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.380 D/GeckoViewSelectionActionDelegate[C]( 4254): handleEvent: updateposition
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.382 D/GeckoViewContent[C]( 4254): handleEvent: mozcaretstatechanged
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.383 W/GeckoViewSelectionActionDelegate[C]( 4254): Stale response org.mozilla.geckoview.COLLAPSE_TO_END
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.385 E/GeckoSessionTestRule( 3142): after evaluate
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.385 D/GeckoViewConsole( 3142): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"4b4d74e0-2391-4bc9-a8aa-0db0593adb52","args":{"oldPrefs":{"geckoview.selection_action.show_on_focus":null,"layout.accessiblecaret.script_change_update_mode":1}},"type":"RestorePrefs"}}
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.386 E/eglCodecCommon( 3142): glUtilsParamSize: unknow param 0x00008caa
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.388 D/GeckoViewScrollDelegate[C]( 4254): handleEvent: mozvisualscroll
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.388 E/GeckoSessionTestRule( 3142): after performTestEndCheck
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.406 D/EGL_emulation( 3142): eglMakeCurrent: 0x7e18a0f619a0: ver 3 0 (tinfo 0x7e18a0f6bc20)
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.407 D/GeckoViewContent( 3142): handleEvent: DOMWindowClose
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.408 D/GeckoViewConsole( 3142): onEvent GeckoView:WebExtension:List null
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.409 D/GeckoViewProgressDelegate[C]( 4254): handleEvent: MozAfterPaint
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  03-06 22:51:08.409 E/GeckoSessionTestRule( 3142): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 collapseToEnd[#textarea](org.mozilla.geckoview.test.SelectionActionDelegateTest)
[task 2021-03-06T22:51:09.223Z] 22:51:09  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.SelectionActionDelegateTest.collapseToEnd[#textarea] | java.lang.AssertionError: Selection offsets should match
[task 2021-03-06T22:51:09.223Z] 22:51:09     INFO -  TEST-INFO took 368ms```

After:

[task 2021-03-06T22:51:08.835Z] 22:51:08     INFO -  TEST-START | org.mozilla.geckoview.test.SelectionActionDelegateTest.collapseToEnd[#textarea]
[task 2021-03-06T22:51:09.043Z] 22:51:09     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=795
[task 2021-03-06T22:51:09.043Z] 22:51:09     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-03-06T22:51:09.043Z] 22:51:09     INFO -  org.mozilla.geckoview.test | Error in collapseToEnd[#textarea](org.mozilla.geckoview.test.SelectionActionDelegateTest):
[task 2021-03-06T22:51:09.043Z] 22:51:09     INFO -  org.mozilla.geckoview.test | java.lang.AssertionError: Selection offsets should match
[task 2021-03-06T22:51:09.043Z] 22:51:09     INFO -  org.mozilla.geckoview.test | Expected: <(5, 5)>
[task 2021-03-06T22:51:09.043Z] 22:51:09     INFO -  org.mozilla.geckoview.test |      but: was <(0, 5)>
[task 2021-03-06T22:51:09.043Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2021-03-06T22:51:09.043Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.Assert.assertThat(Assert.java:956)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector$1.call(ErrorCollector.java:65)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector.checkSucceeds(ErrorCollector.java:78)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector.checkThat(ErrorCollector.java:63)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:826)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.assertThat(BaseSessionTest.kt:111)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest$hasSelectionAt$1.invoke(SelectionActionDelegateTest.kt:486)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest$hasSelectionAt$1.invoke(SelectionActionDelegateTest.kt:34)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.testThat(SelectionActionDelegateTest.kt:242)
[task 2021-03-06T22:51:09.044Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.access$testThat(SelectionActionDelegateTest.kt:34)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest$collapseToEnd$1.invoke(SelectionActionDelegateTest.kt:157)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest$collapseToEnd$1.invoke(SelectionActionDelegateTest.kt:34)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.assumingEditable(SelectionActionDelegateTest.kt:319)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.collapseToEnd(SelectionActionDelegateTest.kt:156)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-03-06T22:51:09.045Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1317)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$cmP_QJg-X16GIlt8KIQd32egmfU.run(lambda)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:154)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-03-06T22:51:09.046Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test |
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=collapseToEnd[#textarea]
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SelectionActionDelegateTest
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.AssertionError: Selection offsets should match
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | Expected: <(5, 5)>
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test |      but: was <(0, 5)>
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.Assert.assertThat(Assert.java:956)
[task 2021-03-06T22:51:09.047Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector$1.call(ErrorCollector.java:65)
[task 2021-03-06T22:51:09.049Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector.checkSucceeds(ErrorCollector.java:78)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector.checkThat(ErrorCollector.java:63)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:826)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.assertThat(BaseSessionTest.kt:111)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest$hasSelectionAt$1.invoke(SelectionActionDelegateTest.kt:486)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest$hasSelectionAt$1.invoke(SelectionActionDelegateTest.kt:34)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.testThat(SelectionActionDelegateTest.kt:242)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.access$testThat(SelectionActionDelegateTest.kt:34)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest$collapseToEnd$1.invoke(SelectionActionDelegateTest.kt:157)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest$collapseToEnd$1.invoke(SelectionActionDelegateTest.kt:34)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.assumingEditable(SelectionActionDelegateTest.kt:319)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.collapseToEnd(SelectionActionDelegateTest.kt:156)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1317)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.-$$Lambda$GeckoSessionTestRule$2$cmP_QJg-X16GIlt8KIQd32egmfU.run(lambda)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:154)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test |
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=520
[task 2021-03-06T22:51:09.050Z] 22:51:09     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2

6c6f5da9-bf33-4082-a19d-7d99e8083d97 Mass rename intermittents due to Bug 1723034.

Summary: Intermittent org.mozilla.geckoview.test.SelectionActionDelegateTest.collapseToEnd[#textarea] | java.lang.AssertionError: Selection offsets should match → Intermittent org.mozilla.geckoview.test.SelectionActionDelegateTest#collapseToEnd[#textarea] | java.lang.AssertionError: Selection offsets should match

Dropping bug 1730998 from the regression field, instead adding bug 1730998 to the blocker instead.

Bug 1730998 makes this failure more frequent. Bug 1730998 raises PAPZ.RequestContentRepaint priority. Anyways there's a race condition in the first place in SelectionActionDelegateChild.jsm.

From a failure log

[task 2021-10-03T10:29:39.215Z] 10:29:39 INFO - 10-03 10:29:38.356 D/GeckoViewSelectionActionDelegateC: handleEvent: updateposition
[task 2021-10-03T10:29:39.215Z] 10:29:39 INFO - 10-03 10:29:38.359 D/GeckoViewContentC: handleEvent: mozcaretstatechanged
[task 2021-10-03T10:29:39.215Z] 10:29:39 INFO - 10-03 10:29:38.359 D/GeckoViewSelectionActionDelegateC: handleEvent: updateposition
[task 2021-10-03T10:29:39.216Z] 10:29:39 INFO - 10-03 10:29:38.361 D/GeckoViewConsole( 3456): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"4d7f6ef1-27e3-4cb7-b4ce-828619b889a5","eval":"[ document.querySelector('#textarea').selectionStart,\ndocument.querySelector('#textarea').selectionEnd ]"}}
[task 2021-10-03T10:29:39.216Z] 10:29:39 INFO - 10-03 10:29:38.361 D/GeckoViewContentC: handleEvent: mozcaretstatechanged
[task 2021-10-03T10:29:39.216Z] 10:29:39 INFO - 10-03 10:29:38.361 D/GeckoViewSelectionActionDelegateC: handleEvent: updateposition
[task 2021-10-03T10:29:39.216Z] 10:29:39 INFO - 10-03 10:29:38.363 D/GeckoViewContentC: handleEvent: mozcaretstatechanged
[task 2021-10-03T10:29:39.216Z] 10:29:39 INFO - 10-03 10:29:38.363 D/GeckoViewProgressDelegateC: handleEvent: MozAfterPaint
[task 2021-10-03T10:29:39.216Z] 10:29:39 INFO - 10-03 10:29:38.364 D/GeckoViewProgress( 3456): receiveMessage: MozAfterPaint
[task 2021-10-03T10:29:39.216Z] 10:29:39 INFO - 10-03 10:29:38.365 W/GeckoViewSelectionActionDelegateC: Stale response org.mozilla.geckoview.COLLAPSE_TO_END

There are three "handleEvent: updateposition"s, thus we hit this condition, then the COLLAPSE_TO_END action wasn't properly handled.

Bug 1730998 raises this racy chance. CCing Agi and Ting-Yu.

Blocks: 1730998
No longer regressed by: 1730998

Now I am mostly 100% sure this is an issue in the test SelectionActionDelegateTest.kt itself. The issue is this delegateDuringNextWait call. As I noted in comment 29, there are multiple "updateposition" events, thus this test needs to call this respondingWith() until the responding action is surely processed.

Honestly I am totally unfamiliar with our GeckoView Junit framework, so I don't have any idea for doing it. (I don't think it can be done without changing SelectionActionDelegateChild.jsm).

A workaround I can think of is, the multiple "updateposition" events are fired in response to scroll operations triggered by this focus() (because it involves a scrollIntoView operation). Avoiding the scroll operations should fix this intermittent.

There are two ways to avoid the scroll operations;

  1. Setting <meta name="viewport" content="width=device-width,initial-scale=0.25"> in inputs.html to avoid overflow contents (this is what I tried in 1730998 comment 19)
  2. Setting a bigger displaysize instead of (100, 100) to avoid overflow

Agi, would either one be acceptable fix here?

Flags: needinfo?(agi)

So if I understand correctly the issue here is that, because we have to scroll, the test gets confused about which events are fired in response to .focus()? The thing I'm confused about is, why are we getting a "stale" event here: Stale response org.mozilla.geckoview.COLLAPSE_TO_END ? Does that mean that the event would be ignored if a user was using the browser?

In general either options would be good (slight preference for 2.) if the bug is not really reproducible on people's phones, which I think it's not, but i don't understand why yet.

Flags: needinfo?(agi)

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

So if I understand correctly the issue here is that, because we have to scroll, the test gets confused about which events are fired in response to .focus()? The thing I'm confused about is, why are we getting a "stale" event here: Stale response org.mozilla.geckoview.COLLAPSE_TO_END ? Does that mean that the event would be ignored if a user was using the browser?

That's a good question. IIUC relevant code, in producation code, this BasicSelectionActionDelegate keeps responding unlike the test does a single shot, isn't it? Of course if a GeckoView embedder does the same manner as what the test does, the same issue will happen there though.

(In reply to Hiroyuki Ikezoe (:hiro) from comment #32)

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

So if I understand correctly the issue here is that, because we have to scroll, the test gets confused about which events are fired in response to .focus()? The thing I'm confused about is, why are we getting a "stale" event here: Stale response org.mozilla.geckoview.COLLAPSE_TO_END ? Does that mean that the event would be ignored if a user was using the browser?

That's a good question. IIUC relevant code, in producation code, this BasicSelectionActionDelegate keeps responding unlike the test does a single shot, isn't it?

hmm, there may be a race condition where an action would be ignored (it's slightly different from this intermittent failure cause though). So, say

  1. SelectionActionDelegateChild.jsm received a "updateposition"
  2. SelectionActionDelegateChild.jsm received a different event, say "releasecaret"
  3. SelectionActionDelegateChild.jsm received another "updateposition"

If all these happened before BasicSelectionActionDelegate responds it, the "releasecaret" event will be lost. Though I am not sure these cases will surely happen or not, it depends on our AccesibleCaret implementation. (Probably Ting-Yu can answer it, he's in CC)

Agi, do you want me to open a new bug for the possible race condition? Would it be ok to tweak SelectionActionDelegateTest.kt as what I suggested in comment 30? We'd like to land bug 1730998 since it's one of our top priority items.

Thanks!

Flags: needinfo?(agi)

(In reply to Hiroyuki Ikezoe (:hiro) from comment #33)

Agi, do you want me to open a new bug for the possible race condition?

Yes please, maybe we can cc :m_kato too he might have ideas.

Would it be ok to tweak SelectionActionDelegateTest.kt as what I suggested in comment 30? We'd like to land bug 1730998 since it's one of our top priority items.

Yes that's fine.

Thank you!

Flags: needinfo?(agi)
See Also: → 1735655

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

(In reply to Hiroyuki Ikezoe (:hiro) from comment #33)

Agi, do you want me to open a new bug for the possible race condition?

Yes please, maybe we can cc :m_kato too he might have ideas.

Filed bug 1735655 with CCing him. Thanks!

SelectionActionDelegateTest does just respond a single event in each test cases,
so if there are multiple events we need to respond, the test stops working since
the response will be discarded in SelectionActionDelegateChild.jsm [1].

We use a lager display size here to avoid the situation, in bug 1735655 the situation
will be eliminated.

[1] https://searchfox.org/mozilla-central/rev/0998b61022a1ece43afe3c750077e5804c6c6392/mobile/android/actors/SelectionActionDelegateChild.jsm#260-264

Assignee: nobody → hikezoe.birchill
Status: NEW → ASSIGNED
Attachment #9245817 - Attachment description: WIP: Bug 1696785 - Use (400x400) display size in SelectionActionDelegateTest to avoid unexpected multiple updateposition events during the test. → Bug 1696785 - Use (400x400) display size in SelectionActionDelegateTest to avoid unexpected multiple updateposition events during the test. r=#geckoview-reviewers
Pushed by hikezoe.birchill@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8b9f0e39e5b1
Use (400x400) display size in SelectionActionDelegateTest to avoid unexpected multiple updateposition events during the test. r=geckoview-reviewers,agi
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: