1891706 - [Android] TypeError: can't access property "remoteTab", this._browser.frameLoader is null

Reporter

Description

•

6 months ago

treeherder

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

This failure starts to happen with the patches on bug 1522790 landed. It's the only wpt test that seems to show a higher occurrence of it.

I'll investigate once bug 1522790 is merged to mozilla-central.

BugBot [:suhaib / :marco/ :calixte]

Comment 1

•

6 months ago

:whimboo, since you are the author of the regressor, bug 1522790, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(hskupin)

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 2

•

6 months ago

Tests that failed because of this error are:

/html/cross-origin-embedder-policy/credentialless/fetch.https.window.html
/html/cross-origin-opener-policy/iframe-popup-same-origin-allow-popups-to-same-origin.https.html

Here the actual stacktrace of the JS code that is failing:
https://treeherder.mozilla.org/logviewer?job_id=454682980&repo=try&lineNumber=3510-3518

[task 2024-04-16T10:31:07.476Z] 10:31:07  WARNING - marionette_driver.errors.UnknownException: TypeError: can't access property "remoteTab", this._browser.frameLoader is null
[task 2024-04-16T10:31:07.476Z] 10:31:07  WARNING - stacktrace:
[task 2024-04-16T10:31:07.476Z] 10:31:07  WARNING - 	maybeCancelContentJSExecution@resource://gre/modules/RemoteWebNavigation.sys.mjs:28:5
[task 2024-04-16T10:31:07.476Z] 10:31:07  WARNING - 	fixupAndLoadURIString@resource://gre/modules/RemoteWebNavigation.sys.mjs:149:37
[task 2024-04-16T10:31:07.476Z] 10:31:07  WARNING - 	fixupAndLoadURIString/<@chrome://global/content/elements/browser-custom-element.js:827:28
[task 2024-04-16T10:31:07.476Z] 10:31:07  WARNING - 	_wrapURIChangeCall@chrome://global/content/elements/browser-custom-element.js:755:9
[task 2024-04-16T10:31:07.476Z] 10:31:07  WARNING - 	fixupAndLoadURIString@chrome://global/content/elements/browser-custom-element.js:826:12
[task 2024-04-16T10:31:07.476Z] 10:31:07  WARNING - 	createNewTab@resource://gre/modules/GeckoViewTestUtils.sys.mjs:58:20

There is something wrong when the initial URL get loaded by opening a new tab/window in GeckoView. But not sure yet if the problem is in createNewTab or is related to a bug in fixupAndLoadURIString.

OS: Unspecified → Android

Summary: Intermittent /html/cross-origin-embedder-policy/credentialless/fetch.https.window.html | TypeError: can't access property "remoteTab", this._browser.frameLoader is null → [Android] TypeError: can't access property "remoteTab", this._browser.frameLoader is null

Henrik Skupin [:whimboo][⌚️UTC+2]

Updated

•

6 months ago

Blocks: 1785603

Comment hidden (Intermittent Failures Robot)

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 4

•

4 months ago

The causing change from bug 1522790 got backed out so it's no longer a regression. I'll take a look once other dependencies for bug 1522790 are done and I can reproduce this issue.

Blocks: 1522790

Flags: needinfo?(hskupin)

Keywords: regression

No longer regressed by: 1522790

Comment hidden (Intermittent Failures Robot)

Henrik Skupin [:whimboo][⌚️UTC+2]

Updated

•

11 days ago

No longer blocks: 1522790

Henrik Skupin [:whimboo][⌚️UTC+2]

Updated

•

10 days ago

Depends on: 1522790

Henrik Skupin [:whimboo][⌚️UTC+2]

Updated

•

10 days ago

status-firefox130: --- → unaffected

status-firefox131: --- → unaffected

status-firefox132: --- → affected

status-firefox-esr115: --- → unaffected

status-firefox-esr128: --- → unaffected

No longer depends on: 1522790

Keywords: regression

Regressed by: 1522790

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 6

•

10 days ago

•

Edited

This actually looks more like a bug in GeckoView. As such moving the bug into the hopefully correct component.

To get more details I've triggered a new try build for specifically those wpt jobs that failed so far which are the chunks 17, 18 and 20:
https://treeherder.mozilla.org/jobs?repo=try&revision=2082675af7344c7380b0d3b0896ef030fd7259f7

status-firefox-esr115: unaffected → ---

status-firefox-esr128: unaffected → ---

Component: web-platform-tests → General

Product: Testing → GeckoView

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 7

•

10 days ago

Some random ideas:

When the browser for the new tab is created, is there an initial load of about:blank?
If yes, we wait for browser-delayed-startup-finished but that doesn't actually mean that the initial page load is done? Maybe we need an extra listener for the load event so we do not run into a race when the frame loader is replaced?
Should we trigger a load to about:blank again when the tab was already created with about:blank?

Henrik Skupin [:whimboo][⌚️UTC+2]

Updated

•

10 days ago

Updated

•

10 days ago

Comment 8

•

10 days ago

Here is a test failure:
https://treeherder.mozilla.org/logviewer?job_id=475106192&repo=try&lineNumber=4915

And an excerpt from the Android log which looks kinda strange due to all the duplicated observer notifications. Especially I wonder why we get those domwindowopened notifications which usually do not appear for all the other tests:

09-20 07:38:24.958 25127 25142 I Gecko   : 1726817904958	Marionette	DEBUG	2 -> [0,351,"WebDriver:NewWindow",{"type":"tab","focus":true,"private":false}]
09-20 07:38:24.960 25127 25142 I Gecko   : 1726817904960	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.960 25198 25241 D EGL_emulation: eglMakeCurrent: 0x783f07a7c1c0: ver 3 0 (tinfo 0x783efd19cda0)
09-20 07:38:24.961 25198 25241 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
09-20 07:38:24.962 25127 25142 I Gecko   : 1726817904962	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.964 25127 25142 I Gecko   : 1726817904964	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.965 25127 25142 I Gecko   : 1726817904965	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.965 25127 25142 I Gecko   : 1726817904965	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.966 25127 25142 I Gecko   : 1726817904966	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.967 25127 25142 I Gecko   : 1726817904967	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.967 25127 25142 I Gecko   : 1726817904967	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.968 25127 25142 I Gecko   : 1726817904968	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.969 25127 25142 I Gecko   : 1726817904969	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.970 25127 25142 I Gecko   : 1726817904970	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.971 25127 25142 I Gecko   : 1726817904970	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.972 25127 25142 I Gecko   : 1726817904972	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-20 07:38:24.978 25127 25142 I Gecko   : 1726817904978	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.978 25127 25142 I Gecko   : 1726817904978	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.978 25127 25142 I Gecko   : 1726817904978	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.979 25127 25142 I Gecko   : 1726817904979	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.979 25127 25142 I Gecko   : 1726817904979	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.979 25127 25142 I Gecko   : 1726817904979	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.980 25127 25142 I Gecko   : 1726817904980	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.980 25127 25142 I Gecko   : 1726817904980	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.980 25127 25142 I Gecko   : 1726817904980	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.981 25127 25142 I Gecko   : 1726817904981	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.981 25127 25142 I Gecko   : 1726817904981	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.981 25127 25142 I Gecko   : 1726817904981	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.981 25127 25142 I Gecko   : 1726817904981	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.982 25127 25142 I Gecko   : 1726817904982	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.982 25127 25142 I Gecko   : 1726817904982	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.982 25127 25142 I Gecko   : 1726817904982	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.982 25127 25142 I Gecko   : 1726817904982	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.983 25127 25142 I Gecko   : 1726817904983	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.983 25127 25142 I Gecko   : 1726817904983	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.983 25127 25142 I Gecko   : 1726817904983	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.984 25127 25142 I Gecko   : 1726817904983	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.984 25127 25142 I Gecko   : 1726817904984	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.984 25127 25142 I Gecko   : 1726817904984	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.984 25127 25142 I Gecko   : 1726817904984	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.984 25127 25142 I Gecko   : 1726817904984	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.985 25127 25142 I Gecko   : 1726817904984	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.985 25127 25142 I Gecko   : 1726817904985	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.985 25127 25142 I Gecko   : 1726817904985	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.985 25127 25142 I Gecko   : 1726817904985	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.985 25127 25142 I Gecko   : 1726817904985	RemoteAgent	TRACE	Received observer notification domwindowopened
09-20 07:38:24.989 25127 25142 I Gecko   : console.log: "\n*** create new tab\n"
09-20 07:38:24.990 25127 25142 I GeckoConsole: 
09-20 07:38:24.990 25127 25142 I GeckoConsole: *** create new tab
09-20 07:38:24.990 25127 25142 I GeckoDump: 
09-20 07:38:24.990 25127 25142 I GeckoDump: **** Browser: destroyed=undefined docshell=null isRemote=true frameLoader=null

For a job that is passing I can see the number of domwindowopened notifications growing by 1 for each time we call WebDriver:NewWindow as well, which is installed on purpose for the prompt listener.

Henrik Skupin [:whimboo][⌚️UTC+2]

Updated

•

10 days ago

Depends on: 1920053

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 9

•

10 days ago

Bug 1920053 should take care of the above reported observer leak.

Comment hidden (Intermittent Failures Robot)

Henrik Skupin [:whimboo][⌚️UTC+2]

Updated

•

7 days ago

Blocks: 1808554

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 12

•

7 days ago

Maybe we need a similar fix here as done on bug 1766322?

Flags: needinfo?(ohall)

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 13

•

7 days ago

Resetting priority / severity so that the bug can triaged correctly by the GeckoView team.

Severity: S4 → --

Priority: P5 → --

Olivia Hall [:olivia]

Comment 14

•

6 days ago

If yes, we wait for browser-delayed-startup-finished but that doesn't actually mean that the initial page load is done? Maybe we need an extra listener for the load event so we do not run into a race when the frame loader is replaced?

This thought sticks out to me in particular. I saw something interesting in AppUiTestDelegate to try here. I'll send a try up with that added into GeckoViewTestUtils to see if it does anything interesting.

Olivia Hall [:olivia]

Updated

•

5 days ago

Comment 15

•

5 days ago

Olivia, when I checked the code of GeckoViewTestUtils.sys.mjs I can see the following call which already forwards the url to some other code:

      sessionId = await lazy.EventDispatcher.instance.sendRequestForResult({
        type: "GeckoView:Test:NewTab",
        url,
      });

Does that call already load the requested URL? If yes, why do we have to call window.browser.fixupAndLoadURIString() for the URL again?

What makes me wonder is this code in GeckoRuntime.java which seems to always load about:blank. Why do we pass url for the GeckoView:Test:NewTab type if we do not immediately load the final URL but still go through about:blank? Or do I miss something?

We probably have to delay resolving windowPromise until the document.readyState of the new window is complete (and that not for about:blank) or a registered event listener fires the load event.

Olivia Hall [:olivia]

Comment 16

•

4 days ago

Thanks for taking a look! I'll try to figure out more today and also add some links here to help gather info on the problem.

Does that call already load the requested URL? If yes, why do we have to call window.browser.fixupAndLoadURIString() for the URL again?

I'm not sure. I don't think so the more that I look at it. I'm looking deeper into the service worker code. It ends up calling onOpenWindow. For test runner onOpenWindow is implemented here. That then calls onNewSession, which the test runner version implements here. Comment "The URI is provided only for informational purposes. Do not call GeckoSession.load here." seems possibly relevant.

What is interesting is that in no implementation is url ever used meaningfully that was passed here. It really does just seem for informational purposes.

I added some logging and it does seem we never go through GeckoView:LoadUri. So, fixupAndLoadURIString really is what is loading the url.

What makes me wonder is this code in GeckoRuntime.java which seems to always load about:blank. Why do we pass url for the GeckoView:Test:NewTab type if we do not immediately load the final URL but still go through about:blank? Or do I miss something?

final String url = message.getString("url", "about:blank"); should pick url, if url is in the message, and if it is not fallback to the default of about:blank. What is interesting is url is essentially unused and just gets passed around. From what I can tell, we open a session, which I presume opens with about:blank, then fixupAndLoadURIString does the next navigation. I'll try to understand more what opening a session is exactly doing.

We probably have to delay resolving windowPromise until the document.readyState of the new window is complete (and that not for about:blank) or a registered event listener fires the load event.

I'll add some logs and look into this!

I also keep wondering why Agi said this in the past in the bug you linked. I think I did see a set active call in the path, I'll see if that leads anywhere too.

Olivia Hall [:olivia]

Comment 17

•

4 days ago

I also keep wondering why Agi said this in the past in the bug you linked. I think I did see a set active call in the path, I'll see if that leads anywhere too.

onNewSession does pass through the same function as in bug 1766322, which also had a missing frameLoader when we expected one. Bug 1766322's code path changed though in bug 1764998.

I don't know if that thought adds more value, but I think we can assume we don't necessarily have a frameloader after windowPromise. Still not sure why an about: page could be potentially different though.

I'll test waiting for document.readyState and see if I can find out anything new.

Henrik Skupin [:whimboo][⌚️UTC+2]

Updated

•

3 days ago

Blocks: 1919915

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 18

•

3 days ago

I pushed a try build to wait with loading the URL until the initial load is done. Lets see if that works:
https://treeherder.mozilla.org/jobs?repo=try&revision=e9edb77300726af492bca892d583bc1dc0b898b0

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 19

•

2 days ago

I see two test failures for the exact same test (/html/cross-origin-embedder-policy/credentialless/fetch.https.window.html) but only for the Android lite build. Olivia what is special for that build? Is it enough to add ac_add_options --enable-geckoview-lite to the mozconfig to build an artifact build? I tried but I still cannot get this test to fail locally in the emulator.

The added logging shows the following:

09-27 14:35:05.176 20729 20744 I Gecko   : ****** readyState: complete, initial: false
09-27 14:35:05.176 20729 20744 I Gecko   : 
09-27 14:35:05.185 20729 20744 I Gecko   : Marionette threw an error: TypeError: can't access property "remoteTab", this._browser.frameLoader is null

It means when we get the "browser-delayed-startup-finished" notification the document is already loaded and we do not show the initial about:blank. Maybe we could run with the MOZ_LOG="BCWebProgress:5" env set to see if there is some other navigation on going?

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 20

•

2 days ago

Here a new try build with the logging turned on:
https://treeherder.mozilla.org/jobs?repo=try&revision=a12066a75fc12616ff483999178bd2e2790e5a4c

Olivia Hall [:olivia]

Comment 21

•

2 days ago

Olivia what is special for that build?

Should just be the same but without any extra dependencies. IIRC, it was made for people external to Mozilla who might want to use the GeckoView project, so they don't need all the extras. Bug 1709640 seems to collaborate that thought.

Is it enough to add ac_add_options --enable-geckoview-lite to the mozconfig to build an artifact build?

Ohh, not sure if I have ever tried that specifically. I have this in my mozconfig for a standard android artifact build, not sure if that needs it too:

ac_add_options --enable-project=mobile/android
ac_add_options --enable-artifact-builds
ac_add_options --target=aarch64
# # Write build artifacts to:
mk_add_options MOZ_OBJDIR=./objdir-frontend

I usually only do aritifact builds for Fenix specific work, so I haven't spent much time with it.

Maybe we could run with the MOZ_LOG="BCWebProgress:5" env set to see if there is some other navigation on going?

That sounds interesting!

I have a couple of random things I've sent tries up with, but nothing particularly interesting so far. I was looking at AppUiTestDelegate.sys.mjs at one point for ideas.

I still cannot get this test to fail locally in the emulator.

I think I saw it fail once, but might be misremembering or thinking of something else. I have this in my notes as what I was probably running, if it did fail locally:

./mach wpt testing/web-platform/tests/html/semantics/links/links-created-by-a-and-area-elements/target_blank_implicit_noopener_base.html --webdriver-arg=-vv --setpref="fission.disableSessionHistoryInParent=true"  --pause-on-unexpected --repeat-until-unexpected --disable-fission

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 22

•

2 days ago

•

Edited

The generated adb logcat is too huge so it stops around 5min before the failure actually happened. Given that we only see the failure for /html/cross-origin-embedder-policy/credentialless/fetch.https.window.html I'm going to push a new try for just /html/cross-origin-embedder-policy/credentialless/. Lets hope that works and reproduces the failure:

https://treeherder.mozilla.org/jobs?repo=try&revision=d6964fa238731cfc6bfe64e560fe5d424396246d

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 23

•

2 days ago

So here a failing case:

09-27 20:32:44.952  6895  6910 I Gecko   : 1727469164951	Marionette	DEBUG	2 -> [0,197,"WebDriver:NewWindow",{"type":"tab","focus":true,"private":false}]
09-27 20:32:44.955  6895  6910 I Gecko   : 
09-27 20:32:44.955  6895  6910 I Gecko   : 
09-27 20:32:44.955  6895  6910 I Gecko   : ****** href= readyState: complete, initial: false
09-27 20:32:44.955  6895  6910 I Gecko   : 
09-27 20:32:44.956  6895  6910 I Gecko   : 1727469164956	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-27 20:32:44.958  6895  6910 I Gecko   : 1727469164958	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
09-27 20:32:44.962  6895  6910 I Gecko   : 1727469164962	RemoteAgent	TRACE	Received observer notification domwindowopened

The problem seems to be that domwindowopened is not send out first but delayed. That means due to some reason we see two very early browser-delayed-startup-finished notifications and want to load the URL but the actual window that we want to operate on hasn't been opened.

Usually it should look like:

09-27 20:32:59.939  7846  7861 I Gecko   : 1727469179939	Marionette	DEBUG	2 -> [0,52,"WebDriver:NewWindow",{"type":"tab","focus":true,"private":false}]
09-27 20:32:59.946  7846  7861 I Gecko   : 1727469179946	RemoteAgent	TRACE	Received observer notification domwindowopened
[..]
09-27 20:33:00.084  7846  7861 I Gecko   : ****** href=chrome://geckoview/content/geckoview.xhtml readyState: complete, initial: false
09-27 20:33:00.084  7846  7861 I Gecko   : 
09-27 20:33:00.085  7846  7861 I Gecko   : 1727469180084	Marionette	TRACE	Received observer notification browser-delayed-startup-finished