Open Bug 1829615 Opened 3 years ago Updated 1 year ago

Intermittent org.mozilla.geckoview.test.SelectionActionDelegateTest#compareClientRect[#iframe-xorigin] | single tracking bug

Categories

(GeckoView :: General, defect, P5)

All
Android
defect

Tracking

(Not tracked)

REOPENED

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [retriggered][stockwell disabled][fxdroid])

Attachments

(3 files, 1 obsolete file)

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


INFO -  04-24 10:13:33.522 I/Gecko   (31818): Cycle completed at
[task 2023-04-24T10:13:35.042Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Mutex : gfxFontEntry lock
[task 2023-04-24T10:13:35.042Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Deadlock may happen for some other execution
[task 2023-04-24T10:13:35.042Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818):
[task 2023-04-24T10:13:35.042Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): : file /builds/worker/checkouts/gecko/xpcom/threads/BlockingResourceBase.cpp:247
[task 2023-04-24T10:13:35.042Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): [Child 31818, Main Thread] WARNING: Potential deadlock detected:
[task 2023-04-24T10:13:35.042Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Cyclical dependency starts at
[task 2023-04-24T10:13:35.042Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Mutex : gfxFontEntry lock
[task 2023-04-24T10:13:35.042Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Next dependency:
[task 2023-04-24T10:13:35.043Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Mutex : SharedFTFace::mLock (currently acquired)
[task 2023-04-24T10:13:35.043Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Cycle completed at
[task 2023-04-24T10:13:35.043Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Mutex : gfxFontEntry lock
[task 2023-04-24T10:13:35.043Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): Deadlock may happen for some other execution
[task 2023-04-24T10:13:35.043Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818):
[task 2023-04-24T10:13:35.043Z] 10:13:35     INFO -  04-24 10:13:33.522 I/Gecko   (31818): : file /builds/worker/checkouts/gecko/xpcom/threads/BlockingResourceBase.cpp:247
[task 2023-04-24T10:13:35.043Z] 10:13:35     INFO -  04-24 10:13:33.523 I/Gecko   (31703): [Child 31703, Main Thread] WARNING: EditorBase::GetInlineSpellChecker() failed, but ignored: 'NS_SUCCEEDED(rvIgnored)', file /builds/worker/checkouts/gecko/editor/libeditor/EditorBase.cpp:1936
[task 2023-04-24T10:13:35.043Z] 10:13:35     INFO -  04-24 10:13:33.523 I/Gecko   (31703): [Child 31703, Main Thread] WARNING: EditorBase::GetInlineSpellChecker() failed, but ignored: 'NS_SUCCEEDED(rvIgnored)', file /builds/worker/checkouts/gecko/editor/libeditor/EditorBase.cpp:1936
[task 2023-04-24T10:13:35.044Z] 10:13:35     INFO -  04-24 10:13:33.532 D/GeckoViewContentDelegateChild[C](31818): handleEvent: MozFirstContentfulPaint
[task 2023-04-24T10:13:35.044Z] 10:13:35     INFO -  04-24 10:13:33.534 I/Gecko   (31818): [Child 31818, Main Thread] WARNING: '!this->lambda.GetNativeObject()', file /builds/worker/checkouts/gecko/widget/android/GeckoEditableSupport.h:141
[task 2023-04-24T10:13:35.044Z] 10:13:35     INFO -  04-24 10:13:33.538 D/GeckoViewContent[C](31703): handleEvent: pageshow
[task 2023-04-24T10:13:35.044Z] 10:13:35     INFO -  04-24 10:13:33.538 D/GeckoViewProgressDelegate[C](31703): handleEvent: pageshow
[task 2023-04-24T10:13:35.044Z] 10:13:35     INFO -  04-24 10:13:33.539 D/GeckoViewAutoFill[C](31703): handleEvent: pageshow
[task 2023-04-24T10:13:35.044Z] 10:13:35     INFO -  04-24 10:13:33.540 E/eglCodecCommon(15986): glUtilsParamSize: unknow param 0x00008caa
[task 2023-04-24T10:13:35.044Z] 10:13:35     INFO -  04-24 10:13:33.551 D/GeckoViewContentDelegateChild[C](31703): handleEvent: MozFirstContentfulPaint
[task 2023-04-24T10:13:35.044Z] 10:13:35     INFO -  04-24 10:13:33.553 D/GeckoViewContentDelegateChild[C](31703): handleEvent: MozFirstContentfulPaint
[task 2023-04-24T10:13:35.045Z] 10:13:35     INFO -  04-24 10:13:33.554 D/GeckoViewProgress( 3475): ProgressTracker onStateChange: isTopLevel=false, flags=0xc0010, status=NS_OK
[task 2023-04-24T10:13:35.045Z] 10:13:35     INFO -  04-24 10:13:33.555 D/GeckoViewProgress( 3475): StateTracker onStateChange: isTopLevel=false, flags=0xc0010, status=NS_OK loadType=2
[task 2023-04-24T10:13:35.045Z] 10:13:35     INFO -  04-24 10:13:33.566 D/GeckoViewContentDelegateParent( 3475): receiveMessage: DispatcherMessage
[task 2023-04-24T10:13:35.045Z] 10:13:35     INFO -  04-24 10:13:33.570 D/WebExtension( 3475): handleMessage GeckoView:WebExtension:Connect
[task 2023-04-24T10:13:35.045Z] 10:13:35     INFO -  04-24 10:13:33.572 D/GeckoViewProgress( 3475): receiveMessage: pageshow
[task 2023-04-24T10:13:35.045Z] 10:13:35     INFO -  04-24 10:13:33.572 D/GeckoViewProgress( 3475): ProgressTracker handleEvent: pageshow
[task 2023-04-24T10:13:35.045Z] 10:13:35     INFO -  04-24 10:13:33.572 D/GeckoViewProgress( 3475): ProgressTracker updateProgress
<....>

First occurrence in this range of retriggers and backfills is on this merge

Whiteboard: [retriggered]

There have been 60 total failures in the last 7 days.
There are:

  • 32 failures on Android 7.0 x86-64 WebRender debug-isolated-process
  • 20 failures on Android 7.0 x86-64 WebRender debug
  • 2 failures on Android 7.0 x86-64 WebRender opt
  • 4 failures on Android 7.0 x86-64 Lite WebRender opt
  • 1 failure on Android 7.0 x86-64 Shippable WebRender opt
  • 1 failure on Android 7.0 x86-64 Lite WebRender Shippable opt

Recent failure log.


[task 2023-05-29T17:58:34.992Z] 17:58:34     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2023-05-29T17:58:34.992Z] 17:58:34     INFO -  TEST-START | org.mozilla.geckoview.test.SelectionActionDelegateTest#compareClientRect[#iframe-xorigin]
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=1032
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | Error in compareClientRect[#iframe-xorigin](org.mozilla.geckoview.test.SelectionActionDelegateTest):
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | java.lang.AssertionError: Selection rect is not at expected location. aRectF(316.96667, 51.625, 327.70834, 83.125) bRectF(316.96667, 51.625, 327.70834, 83.125)
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | Expected: <true>
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test |      but: was <false>
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.junit.Assert.assertThat(Assert.java:964)
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector$1.call(ErrorCollector.java:77)
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector.checkSucceeds(ErrorCollector.java:90)
[task 2023-05-29T17:58:44.152Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector.checkThat(ErrorCollector.java:75)
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:911)
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.assertThat(BaseSessionTest.kt:147)
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.testClientRect(SelectionActionDelegateTest.kt:591)
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.compareClientRect(SelectionActionDelegateTest.kt:357)
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test |
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=compareClientRect[#iframe-xorigin]
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SelectionActionDelegateTest
[task 2023-05-29T17:58:44.153Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.AssertionError: Selection rect is not at expected location. aRectF(316.96667, 51.625, 327.70834, 83.125) bRectF(316.96667, 51.625, 327.70834, 83.125)
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test | Expected: <true>
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test |      but: was <false>
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.junit.Assert.assertThat(Assert.java:964)
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector$1.call(ErrorCollector.java:77)
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector.checkSucceeds(ErrorCollector.java:90)
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ErrorCollector.checkThat(ErrorCollector.java:75)
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.checkThat(GeckoSessionTestRule.java:911)
[task 2023-05-29T17:58:44.154Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.assertThat(BaseSessionTest.kt:147)
[task 2023-05-29T17:58:44.155Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.testClientRect(SelectionActionDelegateTest.kt:591)
[task 2023-05-29T17:58:44.155Z] 17:58:44     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.SelectionActionDelegateTest.compareClientRect(SelectionActionDelegateTest.kt:357)
[task 2023-05-29T17:58:44.155Z] 17:58:44     INFO -  org.mozilla.geckoview.test |
[task 2023-05-29T17:58:44.155Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=753
[task 2023-05-29T17:58:44.155Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2023-05-29T17:58:44.155Z] 17:58:44     INFO -  Printing logcat for test:
[task 2023-05-29T17:58:44.765Z] 17:58:44     INFO -  05-29 17:58:34.103 E/GeckoSessionTestRule( 3454): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec compareClientRect[#iframe-xorigin](org.mozilla.geckoview.test.SelectionActionDelegateTest)
[task 2023-05-29T17:58:44.765Z] 17:58:44     INFO -  05-29 17:58:34.103 E/GeckoSessionTestRule( 3454): before prepareStatement compareClientRect[#iframe-xorigin](org.mozilla.geckoview.test.SelectionActionDelegateTest)
[task 2023-05-29T17:58:44.765Z] 17:58:44     INFO -  05-29 17:58:34.108 D/EGL_emulation( 2108): eglMakeCurrent: 0x79cb25dc2e20: ver 3 0 (tinfo 0x79cb17ea5ba0)
[task 2023-05-29T17:58:44.765Z] 17:58:44     INFO -  05-29 17:58:34.172 D/GeckoViewStartup( 3454): onEvent GeckoView:StorageDelegate:Attached
[task 2023-05-29T17:58:44.765Z] 17:58:44     INFO -  05-29 17:58:34.173 I/Gecko   ( 3454): nsWindow[0x79cac183a700]::Create 0x0 [0 0 1 1]
[task 2023-05-29T17:58:44.765Z] 17:58:44     INFO -  05-29 17:58:34.190 I/Gecko   ( 3454): nsWindow[0x79cac183a700]::Resize [0.000000 0.000000 400.000000 400.000000] (repaint 0)
<...>
[task 2023-05-29T17:58:44.875Z] 17:58:44     INFO -  05-29 17:58:42.908 E/eglCodecCommon(16131): glUtilsParamSize: unknow param 0x00008caa
[task 2023-05-29T17:58:44.875Z] 17:58:44     INFO -  05-29 17:58:42.921 D/GeckoViewProgressDelegate[C](32373): handleEvent: MozAfterPaint
[task 2023-05-29T17:58:44.875Z] 17:58:44     INFO -  05-29 17:58:42.922 D/GeckoViewProgress( 3454): receiveMessage: MozAfterPaint
[task 2023-05-29T17:58:44.875Z] 17:58:44     INFO -  05-29 17:58:42.928 D/GeckoViewContent[C](32485): handleEvent: mozcaretstatechanged
[task 2023-05-29T17:58:44.875Z] 17:58:44     INFO -  05-29 17:58:42.930 D/GeckoViewSelectionActionDelegate[C](32485): handleEvent: updateposition
[task 2023-05-29T17:58:44.875Z] 17:58:44     INFO -  05-29 17:58:42.933 D/GeckoViewContent[C](32485): handleEvent: mozcaretstatechanged
[task 2023-05-29T17:58:44.875Z] 17:58:44     INFO -  05-29 17:58:42.934 D/GeckoSession( 3454): handleMessage: GeckoView:ShowSelectionAction
[task 2023-05-29T17:58:44.875Z] 17:58:44     INFO -  05-29 17:58:42.934 D/GeckoViewSelectionActionDelegate[C](32485): handleEvent: updateposition
[task 2023-05-29T17:58:44.876Z] 17:58:44     INFO -  05-29 17:58:42.934 E/GeckoSessionTestRule( 3454): after evaluate
[task 2023-05-29T17:58:44.876Z] 17:58:44     INFO -  05-29 17:58:42.934 E/eglCodecCommon(16131): glUtilsParamSize: unknow param 0x00008caa
[task 2023-05-29T17:58:44.876Z] 17:58:44     INFO -  05-29 17:58:42.934 D/GeckoViewProgressDelegate[C](32373): handleEvent: MozAfterPaint
[task 2023-05-29T17:58:44.876Z] 17:58:44     INFO -  05-29 17:58:42.935 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"1c799b5e-a7d8-45dd-86cd-6f509dcbe835","args":{"oldPrefs":{"geckoview.selection_action.show_on_focus":null,"layout.accessiblecaret.script_change_update_mode":1}},"type":"RestorePrefs"}}
[task 2023-05-29T17:58:44.876Z] 17:58:44     INFO -  05-29 17:58:42.935 D/GeckoViewContent[C](32485): handleEvent: mozcaretstatechanged
[task 2023-05-29T17:58:44.876Z] 17:58:44     INFO -  05-29 17:58:42.936 D/GeckoViewSelectionActionDelegate[C](32485): handleEvent: updateposition
[task 2023-05-29T17:58:44.876Z] 17:58:44     INFO -  05-29 17:58:42.940 D/GeckoViewProgress( 3454): receiveMessage: MozAfterPaint
[task 2023-05-29T17:58:44.876Z] 17:58:44     INFO -  05-29 17:58:42.955 D/GeckoViewContentDelegateChild[C](32485): handleEvent: MozFirstContentfulPaint
[task 2023-05-29T17:58:44.877Z] 17:58:44     INFO -  05-29 17:58:42.961 D/GeckoViewContentDelegateParent( 3454): receiveMessage: DispatcherMessage
[task 2023-05-29T17:58:44.877Z] 17:58:44     INFO -  05-29 17:58:42.966 E/GeckoSessionTestRule( 3454): after performTestEndCheck
[task 2023-05-29T17:58:44.877Z] 17:58:44     INFO -  05-29 17:58:42.979 E/eglCodecCommon(16131): glUtilsParamSize: unknow param 0x00008caa
[task 2023-05-29T17:58:44.877Z] 17:58:44     INFO -  05-29 17:58:43.028 D/EGL_emulation(16131): eglMakeCurrent: 0x79cb25c9e1a0: ver 3 0 (tinfo 0x79cb25d09b00)
[task 2023-05-29T17:58:44.877Z] 17:58:44     INFO -  05-29 17:58:43.031 D/GeckoViewProgressDelegate[C](32373): handleEvent: MozAfterPaint
[task 2023-05-29T17:58:44.877Z] 17:58:44     INFO -  05-29 17:58:43.031 D/GeckoViewContent( 3454): handleEvent: DOMWindowClose
[task 2023-05-29T17:58:44.877Z] 17:58:44     INFO -  05-29 17:58:43.034 D/GeckoViewConsole( 3454): onEvent GeckoView:WebExtension:List null
[task 2023-05-29T17:58:44.877Z] 17:58:44     INFO -  05-29 17:58:43.038 E/GeckoSessionTestRule( 3454): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 compareClientRect[#iframe-xorigin](org.mozilla.geckoview.test.SelectionActionDelegateTest)
[task 2023-05-29T17:58:44.878Z] 17:58:44  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.SelectionActionDelegateTest#compareClientRect[#iframe-xorigin] | java.lang.AssertionError: Selection rect is not at expected location. aRectF(316.96667, 51.625, 327.70834, 83.125) bRectF(316.96667, 51.625, 327.70834, 83.125)
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  TEST-INFO took 9825ms
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=1032
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=collapseToEnd[#x-input]
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SelectionActionDelegateTest
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=754
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2023-05-29T17:58:44.878Z] 17:58:44     INFO -  TEST-START | org.mozilla.geckoview.test.SelectionActionDelegateTest#collapseToEnd[#x-input]
[task 2023-05-29T17:58:45.969Z] 17:58:45     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=1032
[task 2023-05-29T17:58:45.969Z] 17:58:45     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=.
[task 2023-05-29T17:58:45.969Z] 17:58:45     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2023-05-29T17:58:45.969Z] 17:58:45     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=collapseToEnd[#x-input]
[task 2023-05-29T17:58:45.969Z] 17:58:45     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.SelectionActionDelegateTest
[task 2023-05-29T17:58:45.969Z] 17:58:45     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=754
[task 2023-05-29T17:58:45.969Z] 17:58:45     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 0
[task 2023-05-29T17:58:45.969Z] 17:58:45     INFO -  TEST-PASS | org.mozilla.geckoview.test.SelectionActionDelegateTest#collapseToEnd[#x-input] | took 1153ms

Hello Irene! As the owner of this component, could you please help us assign the bug to someone?

Thank you!

Flags: needinfo?(bugzeeeeee)
Whiteboard: [retriggered] → [retriggered][stockwell needswork:owner]

Update:
There have been 44 total failures in the last 7 days.
There are:

  • 3 failures on android-em-7-0-x86_64-lite-qr opt
  • 39 failures on android-em-7-0-x86_64-qr debug
  • 1 failure on android-em-7-0-x86_64-shippable-lite-qr opt
  • 1 failure on android-em-7-0-x86_64-shippable-qr opt

Recent failure log.

Keywords: leave-open
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]
Whiteboard: [retriggered][stockwell disabled] → [retriggered][stockwell disable-recommended]
Blocks: 1673729
Flags: needinfo?(bugzeeeeee)

I see that all failures are for Fission, so I am adding this to our Fission project.

Attachment #9339751 - Attachment description: Bug 1829615 - Disable org.mozilla.geckoview.test.SelectionActionDelegateTest#compareClientRect for frequent failures. r=#intermittent-reviewers → Bug 1829615 - Disable org.mozilla.geckoview.test.SelectionActionDelegateTest#compareClientRect on fission for frequent failures. r=#intermittent-reviewers
Pushed by sstanca@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/522fdb5b8cfd Disable org.mozilla.geckoview.test.SelectionActionDelegateTest#compareClientRect on fission for frequent failures. r=intermittent-reviewers,geckoview-reviewers,ahal,owlish
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]
Whiteboard: [retriggered][stockwell disabled] → [retriggered][stockwell disabled][fxdroid]

Hey Makoto, I checked this bug - it still reproduces, here is a try push. You seem to have worked on this functionality, bringing it to Fission. Do you have ideas what might be happening here?

Flags: needinfo?(m_kato)
Assignee: nobody → bugzeeeeee

(In reply to [:owlish] 🦉 PST from comment #21)

Hey Makoto, I checked this bug - it still reproduces, here is a try push. You seem to have worked on this functionality, bringing it to Fission. Do you have ideas what might be happening here?

Although I don't debug this yet, I guess that this test cannot wait for pageload in iframe or selection event by accessible caret in iframe.

Flags: needinfo?(m_kato)

Thank you!

Flags: needinfo?(m_kato)
Flags: needinfo?(m_kato)
Status: NEW → ASSIGNED

Maybe, this is a workaround for it. I cannot find good event to wait for completion of moving position of isolated web content process.
There is no failure on my workstation when I run this for one hours.

--- a/mobile/android/geckoview/src/androidTest/assets/www/selectionAction_frame_xorigin.html
+++ b/mobile/android/geckoview/src/androidTest/assets/www/selectionAction_frame_xorigin.html
@@ -4,20 +4,26 @@
     <script>
       window.addEventListener("message", e => {
         switch (e.data.type) {
           case "focus":
             window.focus();
             break;
 
           case "select": {
-            const text = document.body.firstChild;
-            document
-              .getSelection()
-              .setBaseAndExtent(text, 0, text, e.data.length);
+            // On fission, no way to wait for parent position is changed.
+            // So use requestAnimationFrame as workaround.
+            window.requestAnimationFrame(() => {
+              window.requestAnimationFrame(() => {
+                const text = document.body.firstChild;
+                document
+                  .getSelection()
+                  .setBaseAndExtent(text, 0, text, e.data.length);
+              });
+            });
             break;
           }
 
           case "selectedOffset": {
             const sel = document.getSelection();
             const text = document.body.firstChild;
             if (sel.anchorNode !== text || sel.focusNode !== text) {
               window.parent.postMessage([-1, -1], "*");

The change realized me the reason why just adding contentTransformsReceived() didn't solve this race. The test does just flush pending style changes in the parent document, and we need to make sure that the oop iframe in question is surely re-positioned by the style change. But unfortunately contentTransformsReceived() isn't able to use such kind of purposes. It just ensure the initial layout of oop iframes.

Anyways, I am pretty sure adding two rAFs would not solve the race entirely.

Attachment #9375355 - Attachment description: WIP: Bug 1829615 - fix, maybe → Bug 1829615 - Add wait for contentTransformsReceived

Depends on D199060

Thank you Makoto and Hiro!

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

Anyways, I am pretty sure adding two rAFs would not solve the race entirely.

We should file new issue to flush all children.

I don't think flushing all descendant solves this race. A key factor is that we need to wait for the state where the OOP iframe document got the result via APZ. I am assuming we can tweak the current contentTransformsReceived() here not resolve the Promise immediately if there's already a valid mChildToParentConversionMatrix, instead we wait for a new matrix from APZ and resolve the Promise.

An alternative solution here is to use independent static HTMLs and use contentTransformsReceived(), rather than changing styles dynamically.

If the test failed with the alternative solution, it means there's at least one race which is unrelated to contentTransformsReceived.

Attachment #9378429 - Attachment description: Bug 1829615 - Make sure we wait for parent position change → Bug 1829615 - Add wait for contentTransformsReceived

Would you two be interested in the results of my investigation in any way? I have been debugging this, and I got pretty deep into APZ code, I was consulting with Botond. I can add my notes to this bug, if you are interested.

I did run the test locally for about 10 mins with Makoto's fix, and it passed all the time.

Yeah, I am interested in the result with the alternative approach in comment 31.

So, the reason for the intermittent failure is that we seem to be intermittently getting wrong transform matrixes from APZ.

My debugging revealed that in no-fis:

  • we only receive one transform (HitTestingTreeNode::GetTransformToGecko function, to be precise), and it's an identity matrix.
  • We have one tab ID (I am logging this in BrowserChild::GetChildToParentConversionMatrix by calling GetTabId())
  • and one layer (by layer I mean: the function HitTestingTreeNode::GetTransformToGecko(LayersId aRemoteLayersId) takes in aRemoteLayersId - those layers)
  • the matrix is calculated based on the offset coordinates stored in nsDisplayRemote.mOffset (the function that does that is nsDisplayRemote::UpdateScrollData), and those coordinates are 0;0, so that results in identity matrix.

In Fission:

  • we have more Tab IDs (every top-level page basically has its own),
  • and more layers (namely, three: for the chrome document, for the top-level document, and for the remote iframe).
  • The functions that I mentioned are called many more times, and the resulting transform matrix is sometimes identity, and sometimes it actually has other numbers (because the offset coordinates are different). There are two sets of numbers - correct and incorrect one. The correct one doesn't fail the test even though it's not identity matrix, but they always arrive after the incorrect ones, and that timing issue is causing the intermittent failure.

Just to note, during the test in both fis and no-fis we always have one widget - I confirmed that by logging the memory address of this object in SendSubtreeTransformsToChromeMainThread function).

So, to try to get down to the source of the wrong matrixes, I reached this:

  • The incorrect numbers come from nsDisplayRemote.mOffset. That is set by nsDisplayRemote::CreateWebRenderCommands function, and in there layerOffset variable seems to be the culprit.
  • That variable is calculated from two parts, aDisplayListBuilder->ToReferenceFrame(mFrame) call and destRect.TopLeft() call.
  • There is something wront with destRect.
  • Also, aDisplayListBuilder->ToReferenceFrame calls a function that is calculating the reference point from the frame, nsDisplayListBuilder::FindReferenceFrameFor. In that function, there is a loop while (f && f != aOther), which gets 3 iterations to update the docOffset var. The difference between the iterations is always the same, [480; 480], so it's the very first call to f->GetPosition() that returns incorrect coordinates, they are the top left point of nsIFrame.mRect.

At that point, I did not know how to proceed, so I consulted with Botond. I also slacked Makoto (without describing the above - it's too much text to just dump on people), and Makoto suggested making a change to the test, which I did, and it worked, so I made a patch.

Hopefully this makes sense, feel free to ask questions (also, Botond CCed himself on this bug, so feel free to ask him questions as well).

Thanks owlish! That totally makes sense to me, and indeed it matches what I was suspecting.

(In reply to [:owlish] 🦉 PST from comment #34)

In Fission:

  • The functions that I mentioned are called many more times, and the resulting transform matrix is sometimes identity, and sometimes it actually has other numbers (because the offset coordinates are different). There are two sets of numbers - correct and incorrect one. The correct one doesn't fail the test even though it's not identity matrix, but they always arrive after the incorrect ones, and that timing issue is causing the intermittent failure.

So from what I can tell is that contentTransformsReceived does just ensure that the first matrix has been arrived, it doesn't ensure the offset which is set in the test has been reflected into the incoming matries. Say, for example, given that the OOP iframe's border style is initially 0px, and a paint happened there, and the style is updated to 10px, then even if we call await contentTransformsReceived(), after the call it doesn't ensure that the 10px is included the arrived matrix. But if the initial border style is 10px in the first place, await contentTransformsReceived() ensures that the matrix includes the 10px. That's the alternative approach in comment 31.

Personally I prefer the alternative. Just adding timeout-ish things will hide potential regressions. And theoretically even with two rAFs in the OOP iframe process the test can fail, if the parent document was busy after the style change but if the OOP iframe wasn't busy at all, can spins two rAFs, the test will definitely fail because of the same reason of this intermittent.

And now I realized a mistake in D199060. contentTransformsReceived() needs to be called in the OOP iframe's document rather than the parent document. I am sorry I should have noticed it when I first looked it.

Attachment #9378429 - Attachment description: Bug 1829615 - Add wait for contentTransformsReceived → Bug 1829615 - Make sure we wait for changes from parent
Pushed by istorozhko@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/0a07b15df232 Add wait for contentTransformsReceived r=geckoview-reviewers,m_kato
Pushed by istorozhko@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f92c77fccb76 Make sure we wait for changes from parent r=geckoview-reviewers,m_kato
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED

This is still happening: https://treeherder.mozilla.org/logviewer?job_id=447010597&repo=autoland&lineNumber=17693
Failure line change to: TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.SelectionActionDelegateTest#compareClientRect[#iframe-xorigin] | java.lang.AssertionError: Selection rect is not at expected location. aRectF(316.96667, 51.625, 327.70834, 83.125) bRectF(18.0, 140.125, 28.741667, 171.625) expectedDiffRectF(10.0, 10.0, 10.0, 10.0)

Can you please take another look at this?
Thank you!

Status: RESOLVED → REOPENED
Flags: needinfo?(bugzeeeeee)
Resolution: FIXED → ---
Attachment #9383415 - Attachment is obsolete: true

Will look, thank you!

Flags: needinfo?(bugzeeeeee)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: