1673953 - [gv-junit-fis] Run GeckoSessionTestRuleTest on Fission

Status: NEW

(GeckoView :: Sandboxing, task, P2)

Description

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

This bug tracks enabling all GeckoSessionTestRuleTest to run on Fission.

Looks like enabling them triggers Bug 1657028.

Comment 1

[Chris Peterson [:cpeterson]]

Tracking this bug for Android Fission milestone M2 (pass tests with Fission enabled).

Comment 2

[Chris Peterson [:cpeterson]]

Moving Android Fission bugs to the new GeckoView::Sandboxing component.

Comment 3

[[:owlish] 🦉 PST]

This might be something in our testing framework, or some timing issue. The two affected tests fail only when you run the whole suite. There are timeouts when awaiting for the page stop in across-session creation. Tests affected are:

• GeckoSessionTestRuleTest#createOpenSession_canInterleaveOtherCalls
• GeckoSessionTestRuleTest#waitForPageStops_acrossSessionCreation

The third test, GeckoSessionTestRuleTest#contentCrashIgnored fails even without Fission, we need a separate bug for that one

Comment 4

[Makoto Kato [:m_kato]]

I think that this issue is 2 or 3 bugs.

contentCrashIgnored

I guess that this issue is ipc:content-shutdown" in GeckoViewContent.sys.mjs. _contentCrashed is still false even if this observer is received.

waitForPageStops_acrossSessionCreation

Previous test (waitForPageStops_withAllSessions) is passed, so when calling mainSession.reload(), we don't detect page stop. We need to debug ProgressTracker etc.

createOpenSession_canInterleaveOtherCalls

This may be same root cause of waitForPageStops_acrossSessionCreation. Although this test calls mainSession.loadTestPath(HELLO_HTML_PATH) twice, we don't detect both page stop. If you found root cause of waitForPageStops_acrossSessionCreation, I guess that you can also fix this issue too.

Comment 5

[Titouan Thibaud [:tthibaud]]

Attachment: WIP: Bug 1673953 - WIP

Comment 6

[[:owlish] 🦉 PST]

Hey Makoto, do you have a space on your plate for this one? Titouan is busy with monorepo / build things

Comment 7

[Makoto Kato [:m_kato]]

Yes

Comment 8

[Makoto Kato [:m_kato]]

waitForPageStops_acrossSessionCreation

With fission

04-18 03:39:02.000  3843  3862 D GeckoViewModule: dispatch GeckoView:Reload, data={"flags":0}
04-18 03:39:02.001  3843  3862 D GeckoViewNavigation: onEvent: event=GeckoView:Reload, data={"flags":0}
04-18 03:39:02.004  3843  3862 D GeckoViewXUL: onEvent GeckoView:UpdateModuleState {"enabled":true,"module":"GeckoViewExperiment"}
...
04-18 03:39:02.322  3843  3862 D GeckoViewProgress: ProgressTracker updateProgress
04-18 03:39:02.322  3843  3862 D GeckoViewProgress: ProgressTracker updateProgress data={"prev":55,"uri":"http://localhost:4245/assets/www/hello.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":true,"parsed":true} progress=100
04-18 03:39:02.323  3843  3843 D GeckoSession: handleMessage GeckoView:ProgressChanged uri=null
04-18 03:39:02.325  3843  3862 D GeckoViewProgress: ProgressTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK
04-18 03:39:02.325  3843  3862 D GeckoViewProgress: ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello.html
04-18 03:39:02.326  3843  3862 D GeckoViewProgress: ProgressTracker stop
04-18 03:39:02.326  3843  3862 D GeckoViewProgress: ProgressTracker updateProgress
04-18 03:39:02.327  3843  3862 D GeckoViewProgress: StateTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK loadType=1
04-18 03:39:02.327  3843  3843 D GeckoSession: handleMessage GeckoView:PageStop uri=null

Single run with fission

04-18 03:47:55.558  8889  8908 D GeckoViewModule: dispatch GeckoView:Reload, data={"flags":0}
04-18 03:47:55.559  8889  8908 D GeckoViewNavigation: onEvent: event=GeckoView:Reload, data={"flags":0}
04-18 03:47:55.562  9022  9037 I Gecko   : [Child 9022, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:494
04-18 03:47:55.566  9044  9044 I ServiceChildProcess: onCreate
04-18 03:47:55.566  8889  8908 D GeckoViewXUL: onEvent GeckoView:UpdateModuleState {"enabled":true,"module":"GeckoViewExperiment"}
04-18 03:47:55.567  8889  8908 D GeckoViewModule: dispatch GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/hello.html","flags":0,"headerFilter":1}
04-18 03:47:55.568  8889  8908 D GeckoViewNavigation: onEvent: event=GeckoView:LoadUri, data={"uri":"http://localhost:4245/assets/www/hello.html","flags":0,"headerFilter":1}
04-18 03:47:55.568  9044  9044 D GeckoThread: State changed to LAUNCHED
04-18 03:47:55.569  9044  9059 I GeckoThread: preparing to run Gecko
04-18 03:47:55.574  8889  8908 I Gecko   : [Parent 8889, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040154 (NS_ERROR_FACTORY_NOT_REGISTERED): file /builds/worker/checkouts/gecko/extensions/spellcheck/src/mozSpellChecker.cpp:379
04-18 03:47:55.574  9044  9059 D GeckoThread: env var: MOZ_CRASHREPORTER=1
...
04-18 03:47:55.585  8889  8908 D GeckoViewProgress: ProgressTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_BINDING_ABORTED
04-18 03:47:55.585  8889  8908 D GeckoViewProgress: ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello.html
04-18 03:47:55.585  8889  8908 D GeckoViewProgress: ProgressTracker stop
04-18 03:47:55.585  8889  8908 D GeckoViewProgress: ProgressTracker updateProgress
04-18 03:47:55.585  8889  8908 D GeckoViewProgress: ProgressTracker updateProgress data={"prev":15,"uri":"http://localhost:4245/assets/www/hello.html","locationChange":false,"pageStart":true,"pageStop":true,"firstPaint":false,"pageShow":false,"parsed":false} progress=100
04-18 03:47:55.586  8889  8908 D GeckoViewProgress: StateTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_BINDING_ABORTED loadType=1
04-18 03:47:55.587  8889  8889 D GeckoSession: handleMessage GeckoView:ProgressChanged uri=null
04-18 03:47:55.587  8889  8889 D GeckoSession: handleMessage GeckoView:PageStop uri=null
...
04-18 03:47:55.903  8889  8908 D GeckoViewProgress: ProgressTracker updateProgress data={"prev":55,"uri":"http://localhost:4245/assets/www/hello.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":true,"parsed":true} progress=100
04-18 03:47:55.904  8889  8889 D GeckoSession: handleMessage GeckoView:ProgressChanged uri=null
04-18 03:47:55.907  8889  8908 D GeckoViewProgress: ProgressTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK
04-18 03:47:55.907  9044  9059 D GeckoViewContentDelegateChild[C]: handleEvent: DOMContentLoaded
04-18 03:47:55.907  8889  8908 D GeckoViewProgress: ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello.html
04-18 03:47:55.907  8889  8908 D GeckoViewProgress: ProgressTracker stop
04-18 03:47:55.907  8889  8908 D GeckoViewProgress: ProgressTracker updateProgress
04-18 03:47:55.908  8889  8908 D GeckoViewProgress: StateTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK loadType=1
04-18 03:47:55.908  8889  8889 D GeckoSession: handleMessage GeckoView:PageStop uri=null
...
04-18 03:47:55.913  8889  8908 D GeckoViewProgress: ProgressTracker updateProgress data={"prev":55,"uri":"http://localhost:4245/assets/www/hello.html","locationChange":true,"pageStart":true,"pageStop":false,"firstPaint":false,"pageShow":true,"parsed":true} progress=100
04-18 03:47:55.913  9044  9059 I Gecko   : [Child 9044, Main Thread] WARNING: '!this->lambda.GetNativeObject()', file /builds/worker/checkouts/gecko/widget/android/GeckoEditableSupport.h:141
04-18 03:47:55.914  8889  8889 D GeckoSession: handleMessage GeckoView:ProgressChanged uri=null
04-18 03:47:55.915  8889  8908 D GeckoViewProgress: ProgressTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK
04-18 03:47:55.915  8889  8908 D GeckoViewProgress: ProgressTracker onStateChange: uri=http://localhost:4245/assets/www/hello.html
04-18 03:47:55.916  8889  8908 D GeckoViewProgress: ProgressTracker stop
04-18 03:47:55.916  8889  8908 D GeckoViewProgress: ProgressTracker updateProgress
04-18 03:47:55.916  8889  8908 D GeckoViewProgress: StateTracker onStateChange: isTopLevel=true, flags=0xc0010, status=NS_OK loadType=1
04-18 03:47:55.916  8889  8889 D GeckoSession: handleMessage GeckoView:PageStop uri=null

Page stop count is different...

Comment 9

[[:owlish] 🦉 PST]

yes, in our debugging we discovered that page start count is also different, we have one less in Fission. We thought there was some trouble with reload, the way it's working on Fission

Comment 10

[Makoto Kato [:m_kato]]

https://searchfox.org/mozilla-central/rev/8c3ca2f5a74e0ba59c3d9dddf5468a2ffab13467/docshell/base/BrowsingContextWebProgress.cpp#221-227 why start isn't called. When "GeckoView:Reload", if no fission, BrowsingContextWebProgress::OnStateChange with stop then, BrowsingContextWebProgress::OnStateChange with start. But if not fission, BrowsingContextWebProgress::OnStateChange with stop isn't called. I am looking for why stop isn't called on Gecko side.

Comment 11

[Titouan Thibaud [:tthibaud]]

I'll try to capture here the results of our previous investigation.

Reproducing the bug

As the bug is intermittent, this is the way to reliably reproduce it, by running all the tests in a loop until it fails:

./mach geckoview-junit org.mozilla.geckoview.test.GeckoSessionTestRuleTest --run-until-failure

As running all the tests take time, I disabled almost all the tests and kept only:

• waitForPageStops
• createOpenSession_canInterleaveOtherCalls
• waitForPageStops_acrossSessionCreation

Last findings

https://searchfox.org/mozilla-central/source/docshell/base/nsDocShell.cpp#9336

When the bug happens, this line is not reached (it is when the bug doesn't happen). It seems to mean that the load is not considered a reload for some reason, that I haven't identified.

Comment 12

[Makoto Kato [:m_kato]]

Thank you for information. This issue occurs during process switching.

This issue may seem to be a timing issue. During switching process (destroying BrowserChild's window then new window is created), when nsDocLoader::Stop tries to set ABORT, BrowserChild doesn't register nsIWebProgressListener during this. So NS_BINDING_ABORTED isn't sent to Parent process. After completed for process switching, when DocLoader tries to send page start, status is loading, so PageStart won't occur too. But this is same URI request, so the consistency for loading is no problem as result... Hmm.....